Enhancements on wasm function execution time statistic (bytecodeallia…

…nce#2985)

Enhance the statistic of wasm function execution time, or the performance
profiling feature:
- Add os_time_thread_cputime_us() to get the cputime of a thread,
  and use it to calculate the execution time of a wasm function
- Support the statistic of the children execution time of a function,
  and dump it in wasm_runtime_dump_perf_profiling
- Expose two APIs:
  wasm_runtime_sum_wasm_exec_time
  wasm_runtime_get_wasm_func_exec_time

And rename os_time_get_boot_microsecond to os_time_get_boot_us.

core/iwasm/aot/aot_runtime.c

@@ -2807,7 +2807,7 @@ aot_alloc_frame(WASMExecEnv *exec_env, uint32 func_index)
     }
 
 #if WASM_ENABLE_PERF_PROFILING != 0
-    frame->time_started = os_time_get_boot_microsecond();
+    frame->time_started = os_time_thread_cputime_us();
     frame->func_perf_prof_info = func_perf_prof;
 #endif
 
@@ -2826,8 +2826,13 @@ aot_free_frame(WASMExecEnv *exec_env)
 
 #if WASM_ENABLE_PERF_PROFILING != 0
     cur_frame->func_perf_prof_info->total_exec_time +=
-        os_time_get_boot_microsecond() - cur_frame->time_started;
+        os_time_thread_cputime_us() - cur_frame->time_started;
     cur_frame->func_perf_prof_info->total_exec_cnt++;
+
+    /* parent function */
+    if (prev_frame)
+        prev_frame->func_perf_prof_info->children_exec_time =
+            cur_frame->func_perf_prof_info->total_exec_time;
 #endif
 
     wasm_exec_env_free_wasm_frame(exec_env, cur_frame);
@@ -2964,21 +2969,64 @@ aot_dump_perf_profiling(const AOTModuleInstance *module_inst)
 
     os_printf("Performance profiler data:\n");
     for (i = 0; i < total_func_count; i++, perf_prof++) {
+        if (perf_prof->total_exec_cnt == 0)
+            continue;
+
         func_name = get_func_name_from_index(module_inst, i);
 
         if (func_name)
             os_printf(
                 "  func %s, execution time: %.3f ms, execution count: %" PRIu32
-                " times\n",
+                " times, children execution time: %.3f ms\n",
                 func_name, perf_prof->total_exec_time / 1000.0f,
-                perf_prof->total_exec_cnt);
+                perf_prof->total_exec_cnt,
+                perf_prof->children_exec_time / 1000.0f);
         else
             os_printf("  func %" PRIu32
                       ", execution time: %.3f ms, execution count: %" PRIu32
-                      " times\n",
+                      " times, children execution time: %.3f ms\n",
                       i, perf_prof->total_exec_time / 1000.0f,
-                      perf_prof->total_exec_cnt);
+                      perf_prof->total_exec_cnt,
+                      perf_prof->children_exec_time / 1000.0f);
+    }
+}
+
+double
+aot_summarize_wasm_execute_time(const AOTModuleInstance *inst)
+{
+    double ret = 0;
+
+    AOTModule *module = (AOTModule *)inst->module;
+    uint32 total_func_count = module->import_func_count + module->func_count, i;
+
+    for (i = 0; i < total_func_count; i++) {
+        AOTFuncPerfProfInfo *perf_prof =
+            (AOTFuncPerfProfInfo *)inst->func_perf_profilings + i;
+        ret += (perf_prof->total_exec_time - perf_prof->children_exec_time)
+               / 1000.0f;
     }
+
+    return ret;
+}
+
+double
+aot_get_wasm_func_exec_time(const AOTModuleInstance *inst,
+                            const char *func_name)
+{
+    AOTModule *module = (AOTModule *)inst->module;
+    uint32 total_func_count = module->import_func_count + module->func_count, i;
+
+    for (i = 0; i < total_func_count; i++) {
+        const char *name_in_wasm = get_func_name_from_index(inst, i);
+        if (name_in_wasm && strcmp(func_name, name_in_wasm) == 0) {
+            AOTFuncPerfProfInfo *perf_prof =
+                (AOTFuncPerfProfInfo *)inst->func_perf_profilings + i;
+            return (perf_prof->total_exec_time - perf_prof->children_exec_time)
+                   / 1000.0f;
+        }
+    }
+
+    return -1.0;
 }
 #endif /* end of WASM_ENABLE_PERF_PROFILING */
 

core/iwasm/aot/aot_runtime.h

@@ -286,6 +286,8 @@ typedef struct AOTFuncPerfProfInfo {
     uint64 total_exec_time;
     /* total execution count */
     uint32 total_exec_cnt;
+    /* children execution time */
+    uint64 children_exec_time;
 } AOTFuncPerfProfInfo;
 
 /* AOT auxiliary call stack */
@@ -613,6 +615,13 @@ aot_dump_call_stack(WASMExecEnv *exec_env, bool print, char *buf, uint32 len);
 void
 aot_dump_perf_profiling(const AOTModuleInstance *module_inst);
 
+double
+aot_summarize_wasm_execute_time(const AOTModuleInstance *inst);
+
+double
+aot_get_wasm_func_exec_time(const AOTModuleInstance *inst,
+                            const char *func_name);
+
 const uint8 *
 aot_get_custom_section(const AOTModule *module, const char *name, uint32 *len);
 

core/iwasm/common/wasm_runtime_common.c

@@ -1690,8 +1690,43 @@ wasm_runtime_dump_perf_profiling(WASMModuleInstanceCommon *module_inst)
     }
 #endif
 }
+
+double
+wasm_runtime_sum_wasm_exec_time(WASMModuleInstanceCommon *inst)
+{
+#if WASM_ENABLE_INTERP != 0
+    if (inst->module_type == Wasm_Module_Bytecode)
+        return wasm_summarize_wasm_execute_time((WASMModuleInstance *)inst);
 #endif
 
+#if WASM_ENABLE_AOT != 0
+    if (inst->module_type == Wasm_Module_AoT)
+        return aot_summarize_wasm_execute_time((AOTModuleInstance *)inst);
+#endif
+
+    return 0.0;
+}
+
+double
+wasm_runtime_get_wasm_func_exec_time(WASMModuleInstanceCommon *inst,
+                                     const char *func_name)
+{
+#if WASM_ENABLE_INTERP != 0
+    if (inst->module_type == Wasm_Module_Bytecode)
+        return wasm_get_wasm_func_exec_time((WASMModuleInstance *)inst,
+                                            func_name);
+#endif
+
+#if WASM_ENABLE_AOT != 0
+    if (inst->module_type == Wasm_Module_AoT)
+        return aot_get_wasm_func_exec_time((AOTModuleInstance *)inst,
+                                           func_name);
+#endif
+
+    return 0.0;
+}
+#endif /* WASM_ENABLE_PERF_PROFILING != 0 */
+
 WASMModuleInstanceCommon *
 wasm_runtime_get_module_inst(WASMExecEnv *exec_env)
 {

core/iwasm/fast-jit/fe/jit_emit_control.c

@@ -396,9 +396,8 @@ handle_func_return(JitCompContext *cc, JitBlock *block)
 #endif
 
 #if WASM_ENABLE_PERF_PROFILING != 0
-    /* time_end = os_time_get_boot_microsecond() */
-    if (!jit_emit_callnative(cc, os_time_get_boot_microsecond, time_end, NULL,
-                             0)) {
+    /* time_end = os_time_get_boot_us() */
+    if (!jit_emit_callnative(cc, os_time_get_boot_us, time_end, NULL, 0)) {
         return false;
     }
     /* time_start = cur_frame->time_started */

core/iwasm/fast-jit/jit_frontend.c

@@ -1157,11 +1157,10 @@ init_func_translation(JitCompContext *cc)
     func_inst = jit_cc_new_reg_ptr(cc);
 #if WASM_ENABLE_PERF_PROFILING != 0
     time_started = jit_cc_new_reg_I64(cc);
-    /* Call os_time_get_boot_microsecond() to get time_started firstly
+    /* Call os_time_get_boot_us() to get time_started firstly
        as there is stack frame switching below, calling native in them
        may cause register spilling work inproperly */
-    if (!jit_emit_callnative(cc, os_time_get_boot_microsecond, time_started,
-                             NULL, 0)) {
+    if (!jit_emit_callnative(cc, os_time_get_boot_us, time_started, NULL, 0)) {
         return NULL;
     }
 #endif

core/iwasm/include/wasm_export.h

@@ -1274,6 +1274,26 @@ wasm_runtime_dump_mem_consumption(wasm_exec_env_t exec_env);
 WASM_RUNTIME_API_EXTERN void
 wasm_runtime_dump_perf_profiling(wasm_module_inst_t module_inst);
 
+/**
+ * Return total wasm functions' execution time in ms
+ *
+ * @param module_inst the WASM module instance to profile
+ */
+WASM_RUNTIME_API_EXTERN double
+wasm_runtime_sum_wasm_exec_time(wasm_module_inst_t module_inst);
+
+/**
+ * Return execution time in ms of a given wasm funciton with
+*  func_name. If the function is not found, return 0.
+ *
+ * @param module_inst the WASM module instance to profile
+ * @param func_name could be an export name or a name in the
+ *                  name section
+ */
+WASM_RUNTIME_API_EXTERN double
+wasm_runtime_get_wasm_func_exec_time(wasm_module_inst_t inst,
+                                     const char *func_name);
+
 /* wasm thread callback function type */
 typedef void *(*wasm_thread_callback_t)(wasm_exec_env_t, void *);
 /* wasm thread type */

core/iwasm/interpreter/wasm_interp_classic.c

@@ -850,7 +850,7 @@ ALLOC_FRAME(WASMExecEnv *exec_env, uint32 size, WASMInterpFrame *prev_frame)
     if (frame) {
         frame->prev_frame = prev_frame;
 #if WASM_ENABLE_PERF_PROFILING != 0
-        frame->time_started = os_time_get_boot_microsecond();
+        frame->time_started = os_time_thread_cputime_us();
 #endif
     }
     else {
@@ -866,9 +866,14 @@ FREE_FRAME(WASMExecEnv *exec_env, WASMInterpFrame *frame)
 {
 #if WASM_ENABLE_PERF_PROFILING != 0
     if (frame->function) {
+        WASMInterpFrame *prev_frame = frame->prev_frame;
         frame->function->total_exec_time +=
-            os_time_get_boot_microsecond() - frame->time_started;
+            os_time_thread_cputime_us() - frame->time_started;
         frame->function->total_exec_cnt++;
+
+        if (prev_frame && prev_frame->function)
+            prev_frame->function->children_exec_time +=
+                frame->function->total_exec_time;
     }
 #endif
     wasm_exec_env_free_wasm_frame(exec_env, frame);

core/iwasm/interpreter/wasm_interp_fast.c

@@ -884,7 +884,7 @@ ALLOC_FRAME(WASMExecEnv *exec_env, uint32 size, WASMInterpFrame *prev_frame)
     if (frame) {
         frame->prev_frame = prev_frame;
 #if WASM_ENABLE_PERF_PROFILING != 0
-        frame->time_started = os_time_get_boot_microsecond();
+        frame->time_started = os_time_thread_cputime_us();
 #endif
     }
     else {
@@ -900,9 +900,15 @@ FREE_FRAME(WASMExecEnv *exec_env, WASMInterpFrame *frame)
 {
 #if WASM_ENABLE_PERF_PROFILING != 0
     if (frame->function) {
+        WASMInterpFrame *prev_frame = frame->prev_frame;
+
         frame->function->total_exec_time +=
-            os_time_get_boot_microsecond() - frame->time_started;
+            os_time_thread_cputime_us() - frame->time_started;
         frame->function->total_exec_cnt++;
+
+        if (prev_frame && prev_frame->function)
+            prev_frame->function->children_exec_time +=
+                frame->function->total_exec_time;
     }
 #endif
     wasm_exec_env_free_wasm_frame(exec_env, frame);