Enhance memory profiling with structured logging support

TianlongLiang · TianlongLiang · commit 7c0471097dc0 · 2026-03-31T13:29:22.000+08:00
- Enable memory profiling and structured logging in CMake configuration.
- Update memory tracing definitions to support custom sections.
- Replace os_printf with MEM_PROF_PRINTF for memory-related outputs.
- Add verbose logging for memory consumption in various modules.
diff --git a/build-scripts/SConscript_config b/build-scripts/SConscript_config
@@ -103,6 +103,14 @@ if GetDepend(['WAMR_BUILD_MEMORY_PROFILING']):
     CPPDEFINES += ['WASM_ENABLE_MEMORY_PROFILING=1']
     print('[WAMR] Memory profiling enabled')
 
+if GetDepend(['WAMR_BUILD_MEM_PROFILING_USE_LOG']):
+    CPPDEFINES += ['WASM_MEM_PROFILING_USE_LOG=1']
+    print('[WAMR] Memory profiling uses structured logging')
+
+if GetDepend(['WAMR_BUILD_MEMORY_TRACING']):
+    CPPDEFINES += ['WASM_ENABLE_MEMORY_TRACING=1']
+    print('[WAMR] Memory tracing enabled')
+
 if GetDepend(['WAMR_BUILD_CUSTOM_NAME_SECTION']):
     CPPDEFINES += ['WASM_ENABLE_CUSTOM_NAME_SECTION=1']
     print('[WAMR] Custom name section enabled')
diff --git a/build-scripts/config_common.cmake b/build-scripts/config_common.cmake
@@ -478,6 +478,14 @@ if (WAMR_BUILD_MEMORY_PROFILING EQUAL 1)
   add_definitions (-DWASM_ENABLE_MEMORY_PROFILING=1)
   message ("     Memory profiling enabled")
 endif ()
+if (WAMR_BUILD_MEM_PROFILING_USE_LOG EQUAL 1)
+  add_definitions (-DWASM_MEM_PROFILING_USE_LOG=1)
+  message ("     Memory profiling uses structured logging")
+endif ()
+if (WAMR_BUILD_MEMORY_TRACING EQUAL 1)
+  add_definitions (-DWASM_ENABLE_MEMORY_TRACING=1)
+  message ("     Memory tracing enabled")
+endif ()
 if (WAMR_BUILD_PERF_PROFILING EQUAL 1)
   add_definitions (-DWASM_ENABLE_PERF_PROFILING=1)
   message ("     Performance profiling enabled")
diff --git a/build-scripts/esp-idf/wamr/CMakeLists.txt b/build-scripts/esp-idf/wamr/CMakeLists.txt
@@ -56,6 +56,14 @@ if (NOT CMAKE_BUILD_EARLY_EXPANSION)
     set (WAMR_BUILD_MEMORY_PROFILING 1)
   endif ()
 
+  if (CONFIG_WAMR_ENABLE_MEM_PROFILING_USE_LOG)
+    set (WAMR_BUILD_MEM_PROFILING_USE_LOG 1)
+  endif ()
+
+  if (CONFIG_WAMR_ENABLE_MEMORY_TRACING)
+    set (WAMR_BUILD_MEMORY_TRACING 1)
+  endif ()
+
   if (CONFIG_WAMR_ENABLE_PERF_PROFILING)
     set (WAMR_BUILD_PERF_PROFILING 1)
   endif ()
diff --git a/core/config.h b/core/config.h
@@ -347,6 +347,13 @@ unless used elsewhere */
 #define WASM_ENABLE_MEMORY_TRACING 0
 #endif
 
+/* Use structured logging (LOG_VERBOSE) instead of os_printf for memory
+   profiling/tracing output. When enabled, output respects the log verbose
+   level set by bh_log_set_verbose_level(). */
+#ifndef WASM_MEM_PROFILING_USE_LOG
+#define WASM_MEM_PROFILING_USE_LOG 0
+#endif
+
 /* Performance profiling */
 #ifndef WASM_ENABLE_PERF_PROFILING
 #define WASM_ENABLE_PERF_PROFILING 0
diff --git a/core/iwasm/aot/aot_runtime.c b/core/iwasm/aot/aot_runtime.c
@@ -3781,6 +3781,17 @@ aot_get_module_mem_consumption(const AOTModule *module,
         mem_conspn->aot_code_size += sizeof(uint8) * obj_data->size;
     }
 
+#if WASM_ENABLE_LOAD_CUSTOM_SECTION != 0
+    {
+        WASMCustomSection *section = module->custom_section_list;
+        while (section) {
+            mem_conspn->custom_sections_size +=
+                sizeof(WASMCustomSection) + section->content_len;
+            section = section->next;
+        }
+    }
+#endif
+
     mem_conspn->total_size += mem_conspn->module_struct_size;
     mem_conspn->total_size += mem_conspn->types_size;
     mem_conspn->total_size += mem_conspn->imports_size;
@@ -3793,6 +3804,9 @@ aot_get_module_mem_consumption(const AOTModule *module,
     mem_conspn->total_size += mem_conspn->data_segs_size;
     mem_conspn->total_size += mem_conspn->const_strs_size;
     mem_conspn->total_size += mem_conspn->aot_code_size;
+#if WASM_ENABLE_LOAD_CUSTOM_SECTION != 0
+    mem_conspn->total_size += mem_conspn->custom_sections_size;
+#endif
 }
 
 void
diff --git a/core/iwasm/common/wasm_native.c b/core/iwasm/common/wasm_native.c
@@ -268,7 +268,7 @@ register_natives(const char *module_name, NativeSymbol *native_symbols,
     if (!(node = wasm_runtime_malloc(sizeof(NativeSymbolsNode))))
         return false;
 #if WASM_ENABLE_MEMORY_TRACING != 0
-    os_printf("Register native, size: %u\n", sizeof(NativeSymbolsNode));
+    MEM_PROF_PRINTF("Register native, size: %u\n", sizeof(NativeSymbolsNode));
 #endif
 
     node->module_name = module_name;
diff --git a/core/iwasm/common/wasm_runtime_common.c b/core/iwasm/common/wasm_runtime_common.c
@@ -2029,21 +2029,25 @@ wasm_runtime_dump_module_mem_consumption(const WASMModuleCommon *module)
     }
 #endif
 
-    os_printf("WASM module memory consumption, total size: %u\n",
+    MEM_PROF_PRINTF("WASM module memory consumption, total size: %u\n",
               mem_conspn.total_size);
-    os_printf("    module struct size: %u\n", mem_conspn.module_struct_size);
-    os_printf("    types size: %u\n", mem_conspn.types_size);
-    os_printf("    imports size: %u\n", mem_conspn.imports_size);
-    os_printf("    funcs size: %u\n", mem_conspn.functions_size);
-    os_printf("    tables size: %u\n", mem_conspn.tables_size);
-    os_printf("    memories size: %u\n", mem_conspn.memories_size);
-    os_printf("    globals size: %u\n", mem_conspn.globals_size);
-    os_printf("    exports size: %u\n", mem_conspn.exports_size);
-    os_printf("    table segs size: %u\n", mem_conspn.table_segs_size);
-    os_printf("    data segs size: %u\n", mem_conspn.data_segs_size);
-    os_printf("    const strings size: %u\n", mem_conspn.const_strs_size);
+    MEM_PROF_PRINTF("    module struct size: %u\n", mem_conspn.module_struct_size);
+    MEM_PROF_PRINTF("    types size: %u\n", mem_conspn.types_size);
+    MEM_PROF_PRINTF("    imports size: %u\n", mem_conspn.imports_size);
+    MEM_PROF_PRINTF("    funcs size: %u\n", mem_conspn.functions_size);
+    MEM_PROF_PRINTF("    tables size: %u\n", mem_conspn.tables_size);
+    MEM_PROF_PRINTF("    memories size: %u\n", mem_conspn.memories_size);
+    MEM_PROF_PRINTF("    globals size: %u\n", mem_conspn.globals_size);
+    MEM_PROF_PRINTF("    exports size: %u\n", mem_conspn.exports_size);
+    MEM_PROF_PRINTF("    table segs size: %u\n", mem_conspn.table_segs_size);
+    MEM_PROF_PRINTF("    data segs size: %u\n", mem_conspn.data_segs_size);
+    MEM_PROF_PRINTF("    const strings size: %u\n", mem_conspn.const_strs_size);
+#if WASM_ENABLE_LOAD_CUSTOM_SECTION != 0
+    MEM_PROF_PRINTF("    custom sections size: %u\n",
+              mem_conspn.custom_sections_size);
+#endif
 #if WASM_ENABLE_AOT != 0
-    os_printf("    aot code size: %u\n", mem_conspn.aot_code_size);
+    MEM_PROF_PRINTF("    aot code size: %u\n", mem_conspn.aot_code_size);
 #endif
 }
 
@@ -2066,16 +2070,16 @@ wasm_runtime_dump_module_inst_mem_consumption(
     }
 #endif
 
-    os_printf("WASM module inst memory consumption, total size: %lu\n",
+    MEM_PROF_PRINTF("WASM module inst memory consumption, total size: %lu\n",
               mem_conspn.total_size);
-    os_printf("    module inst struct size: %u\n",
+    MEM_PROF_PRINTF("    module inst struct size: %u\n",
               mem_conspn.module_inst_struct_size);
-    os_printf("    memories size: %lu\n", mem_conspn.memories_size);
-    os_printf("        app heap size: %u\n", mem_conspn.app_heap_size);
-    os_printf("    tables size: %u\n", mem_conspn.tables_size);
-    os_printf("    functions size: %u\n", mem_conspn.functions_size);
-    os_printf("    globals size: %u\n", mem_conspn.globals_size);
-    os_printf("    exports size: %u\n", mem_conspn.exports_size);
+    MEM_PROF_PRINTF("    memories size: %lu\n", mem_conspn.memories_size);
+    MEM_PROF_PRINTF("        app heap size: %u\n", mem_conspn.app_heap_size);
+    MEM_PROF_PRINTF("    tables size: %u\n", mem_conspn.tables_size);
+    MEM_PROF_PRINTF("    functions size: %u\n", mem_conspn.functions_size);
+    MEM_PROF_PRINTF("    globals size: %u\n", mem_conspn.globals_size);
+    MEM_PROF_PRINTF("    exports size: %u\n", mem_conspn.exports_size);
 }
 
 void
@@ -2084,14 +2088,14 @@ wasm_runtime_dump_exec_env_mem_consumption(const WASMExecEnv *exec_env)
     uint32 total_size =
         offsetof(WASMExecEnv, wasm_stack_u.bottom) + exec_env->wasm_stack_size;
 
-    os_printf("Exec env memory consumption, total size: %u\n", total_size);
-    os_printf("    exec env struct size: %u\n",
+    MEM_PROF_PRINTF("Exec env memory consumption, total size: %u\n", total_size);
+    MEM_PROF_PRINTF("    exec env struct size: %u\n",
               offsetof(WASMExecEnv, wasm_stack_u.bottom));
 #if WASM_ENABLE_INTERP != 0 && WASM_ENABLE_FAST_INTERP == 0
-    os_printf("        block addr cache size: %u\n",
+    MEM_PROF_PRINTF("        block addr cache size: %u\n",
               sizeof(exec_env->block_addr_cache));
 #endif
-    os_printf("    stack size: %u\n", exec_env->wasm_stack_size);
+    MEM_PROF_PRINTF("    stack size: %u\n", exec_env->wasm_stack_size);
 }
 
 uint32
@@ -2152,20 +2156,20 @@ wasm_runtime_dump_mem_consumption(WASMExecEnv *exec_env)
                  + exec_env->wasm_stack_size + module_mem_consps.total_size
                  + module_inst_mem_consps.total_size;
 
-    os_printf("\nMemory consumption summary (bytes):\n");
+    MEM_PROF_PRINTF("\nMemory consumption summary (bytes):\n");
     wasm_runtime_dump_module_mem_consumption(module_common);
     wasm_runtime_dump_module_inst_mem_consumption(module_inst_common);
     wasm_runtime_dump_exec_env_mem_consumption(exec_env);
-    os_printf("\nTotal memory consumption of module, module inst and "
+    MEM_PROF_PRINTF("\nTotal memory consumption of module, module inst and "
               "exec env: %" PRIu64 "\n",
               total_size);
-    os_printf("Total interpreter stack used: %u\n",
+    MEM_PROF_PRINTF("Total interpreter stack used: %u\n",
               exec_env->max_wasm_stack_used);
 
     if (max_aux_stack_used != (uint32)-1)
-        os_printf("Total auxiliary stack used: %u\n", max_aux_stack_used);
+        MEM_PROF_PRINTF("Total auxiliary stack used: %u\n", max_aux_stack_used);
     else
-        os_printf("Total aux stack used: no enough info to profile\n");
+        MEM_PROF_PRINTF("Total aux stack used: no enough info to profile\n");
 
     /*
      * Report the native stack usage estimation.
@@ -2177,13 +2181,13 @@ wasm_runtime_dump_mem_consumption(WASMExecEnv *exec_env)
      * It doesn't cover host func implementations, signal handlers, etc.
      */
     if (exec_env->native_stack_top_min != (void *)UINTPTR_MAX)
-        os_printf("Native stack left: %zd\n",
+        MEM_PROF_PRINTF("Native stack left: %zd\n",
                   exec_env->native_stack_top_min
                       - exec_env->native_stack_boundary);
     else
-        os_printf("Native stack left: no enough info to profile\n");
+        MEM_PROF_PRINTF("Native stack left: no enough info to profile\n");
 
-    os_printf("Total app heap used: %u\n", app_heap_peak_size);
+    MEM_PROF_PRINTF("Total app heap used: %u\n", app_heap_peak_size);
 }
 #endif /* end of (WASM_ENABLE_MEMORY_PROFILING != 0) \
                  || (WASM_ENABLE_MEMORY_TRACING != 0) */
diff --git a/core/iwasm/common/wasm_runtime_common.h b/core/iwasm/common/wasm_runtime_common.h
@@ -529,6 +529,9 @@ typedef struct WASMModuleMemConsumption {
     uint32 table_segs_size;
     uint32 data_segs_size;
     uint32 const_strs_size;
+#if WASM_ENABLE_LOAD_CUSTOM_SECTION != 0
+    uint32 custom_sections_size;
+#endif
 #if WASM_ENABLE_AOT != 0
     uint32 aot_code_size;
 #endif
diff --git a/core/iwasm/interpreter/wasm_runtime.c b/core/iwasm/interpreter/wasm_runtime.c
@@ -4214,6 +4214,17 @@ wasm_get_module_mem_consumption(const WASMModule *module,
         }
     }
 
+#if WASM_ENABLE_LOAD_CUSTOM_SECTION != 0
+    {
+        WASMCustomSection *section = module->custom_section_list;
+        while (section) {
+            mem_conspn->custom_sections_size +=
+                sizeof(WASMCustomSection) + section->content_len;
+            section = section->next;
+        }
+    }
+#endif
+
     mem_conspn->total_size += mem_conspn->module_struct_size;
     mem_conspn->total_size += mem_conspn->types_size;
     mem_conspn->total_size += mem_conspn->imports_size;
@@ -4225,6 +4236,9 @@ wasm_get_module_mem_consumption(const WASMModule *module,
     mem_conspn->total_size += mem_conspn->table_segs_size;
     mem_conspn->total_size += mem_conspn->data_segs_size;
     mem_conspn->total_size += mem_conspn->const_strs_size;
+#if WASM_ENABLE_LOAD_CUSTOM_SECTION != 0
+    mem_conspn->total_size += mem_conspn->custom_sections_size;
+#endif
 }
 
 void
diff --git a/core/shared/mem-alloc/ems/ems_kfc.c b/core/shared/mem-alloc/ems/ems_kfc.c
@@ -76,10 +76,10 @@ gc_init_with_pool(char *buf, gc_size_t buf_size)
     heap_max_size = (uint32)(buf_end - base_addr) & (uint32)~7;
 
 #if WASM_ENABLE_MEMORY_TRACING != 0
-    os_printf("Heap created, total size: %u\n", buf_size);
-    os_printf("   heap struct size: %u\n", sizeof(gc_heap_t));
-    os_printf("   actual heap size: %u\n", heap_max_size);
-    os_printf("   padding bytes: %u\n",
+    MEM_PROF_PRINTF("Heap created, total size: %u\n", buf_size);
+    MEM_PROF_PRINTF("   heap struct size: %u\n", sizeof(gc_heap_t));
+    MEM_PROF_PRINTF("   actual heap size: %u\n", heap_max_size);
+    MEM_PROF_PRINTF("   padding bytes: %u\n",
               buf_size - sizeof(gc_heap_t) - heap_max_size);
 #endif
     return gc_init_internal(heap, base_addr, heap_max_size);
@@ -119,11 +119,11 @@ gc_init_with_struct_and_pool(char *struct_buf, gc_size_t struct_buf_size,
     heap_max_size = (uint32)(pool_buf_end - base_addr) & (uint32)~7;
 
 #if WASM_ENABLE_MEMORY_TRACING != 0
-    os_printf("Heap created, total size: %u\n",
-              struct_buf_size + pool_buf_size);
-    os_printf("   heap struct size: %u\n", sizeof(gc_heap_t));
-    os_printf("   actual heap size: %u\n", heap_max_size);
-    os_printf("   padding bytes: %u\n", pool_buf_size - heap_max_size);
+    MEM_PROF_PRINTF("Heap created, total size: %u\n",
+                    struct_buf_size + pool_buf_size);
+    MEM_PROF_PRINTF("   heap struct size: %u\n", sizeof(gc_heap_t));
+    MEM_PROF_PRINTF("   actual heap size: %u\n", heap_max_size);
+    MEM_PROF_PRINTF("   padding bytes: %u\n", pool_buf_size - heap_max_size);
 #endif
     return gc_init_internal(heap, base_addr, heap_max_size);
 }
diff --git a/core/shared/utils/bh_log.h b/core/shared/utils/bh_log.h
@@ -87,6 +87,18 @@ bh_log_proc_mem(const char *function, uint32 line);
 
 #define LOG_PROC_MEM(...) bh_log_proc_mem(__FUNCTION__, __LINE__)
 
+/*
+ * MEM_PROF_PRINTF: output macro for memory profiling/tracing.
+ * When WASM_MEM_PROFILING_USE_LOG is enabled, routes output through
+ * LOG_VERBOSE (respects log level filtering, adds timestamps).
+ * Otherwise, uses os_printf for direct output (original behavior).
+ */
+#if WASM_MEM_PROFILING_USE_LOG != 0
+#define MEM_PROF_PRINTF(...) LOG_VERBOSE(__VA_ARGS__)
+#else
+#define MEM_PROF_PRINTF(...) os_printf(__VA_ARGS__)
+#endif
+
 #ifdef __cplusplus
 }
 #endif
diff --git a/core/shared/utils/uncommon/bh_read_file.c b/core/shared/utils/uncommon/bh_read_file.c
@@ -48,7 +48,7 @@ bh_read_file_to_buffer(const char *filename, uint32 *ret_size)
         return NULL;
     }
 #if WASM_ENABLE_MEMORY_TRACING != 0
-    printf("Read file, total size: %u\n", file_size);
+    MEM_PROF_PRINTF("Read file, total size: %u\n", file_size);
 #endif
 
     read_size = _read(file, buffer, file_size);
@@ -99,7 +99,7 @@ bh_read_file_to_buffer(const char *filename, uint32 *ret_size)
         return NULL;
     }
 #if WASM_ENABLE_MEMORY_TRACING != 0
-    printf("Read file, total size: %u\n", file_size);
+    MEM_PROF_PRINTF("Read file, total size: %u\n", file_size);
 #endif
 
     read_size = (uint32)read(file, buffer, file_size);
diff --git a/doc/build_wamr.md b/doc/build_wamr.md
@@ -79,6 +79,8 @@ add_library(vmlib ${WAMR_RUNTIME_LIB_SOURCE})
 | [WAMR_BUILD_LOAD_CUSTOM_SECTION](#load-wasm-custom-sections)                                             | loading custom sections              |
 | [WAMR_BUILD_MEMORY64](#memory64-feature)                                                                 | memory64 support                     |
 | [WAMR_BUILD_MEMORY_PROFILING](#memory-profiling-experiment)                                              | memory profiling                     |
+| [WAMR_BUILD_MEM_PROFILING_USE_LOG](#memory-profiling-structured-logging)                                 | memory profiling structured logging  |
+| [WAMR_BUILD_MEMORY_TRACING](#memory-tracing)                                                             | memory tracing                       |
 | [WAMR_BUILD_MINI_LOADER](#wasm-mini-loader) :warning: :exclamation:                                      | mini loader                          |
 | [WAMR_BUILD_MODULE_INST_CONTEXT](#module-instance-context-apis)                                          | module instance context              |
 | [WAMR_BUILD_MULTI_MEMORY](#multi-memory)                                                                 | multi-memory support                 |
@@ -384,6 +386,20 @@ SIMDE (SIMD Everywhere) implements SIMD operations in fast interpreter mode.
 > [!NOTE]
 > When enabled, call `void wasm_runtime_dump_mem_consumption(wasm_exec_env_t exec_env)` to dump memory usage. Currently only module, module_instance, and exec_env memory are measured; other components such as `wasi-ctx`, `multi-module`, and `thread-manager` are not included. See [Memory usage estimation for a module](./memory_usage.md).
 
+### **memory profiling structured logging**
+
+- **WAMR_BUILD_MEM_PROFILING_USE_LOG**=1/0, default to off.
+
+> [!NOTE]
+> When enabled, memory profiling and tracing output uses structured logging (`LOG_VERBOSE`) instead of `os_printf`. Output then respects the log verbose level set by `bh_log_set_verbose_level()` and includes timestamps.
+
+### **memory tracing**
+
+- **WAMR_BUILD_MEMORY_TRACING**=1/0, default to off.
+
+> [!NOTE]
+> When enabled, detailed memory allocation and deallocation traces are printed at runtime, which is useful for debugging memory issues.
+
 ### **performance profiling (Experiment)**
 
 - **WAMR_BUILD_PERF_PROFILING**=1/0, default to off.
diff --git a/product-mini/platforms/nuttx/CMakeLists.txt b/product-mini/platforms/nuttx/CMakeLists.txt
@@ -75,9 +75,7 @@ else()
 endif()
 
 if(CONFIG_INTERPRETERS_WAMR_MEMORY_TRACING)
-  add_definitions(-DWASM_ENABLE_MEMORY_TRACING=1)
-else()
-  add_definitions(-DWASM_ENABLE_MEMORY_TRACING=0)
+  set(WAMR_BUILD_MEMORY_TRACING 1)
 endif()
 
 if(CONFIG_INTERPRETERS_WAMR_SHARED_MEMORY)
diff --git a/samples/custom-section/src/main.c b/samples/custom-section/src/main.c
@@ -5,6 +5,7 @@
 
 #include "bh_getopt.h"
 #include "bh_read_file.h"
+#include "bh_log.h"
 #include "wasm_export.h"
 
 int32_t
@@ -79,6 +80,8 @@ main(int argc, char *argv_main[])
         return -1;
     }
 
+    bh_log_set_verbose_level(BH_LOG_LEVEL_VERBOSE);
+
     reset_custom_section_handles();
 
     buffer = bh_read_file_to_buffer(wasm_path, &buf_size);
