From 204ee9d17b387e65820a9f7796eec53aaa664b96 Mon Sep 17 00:00:00 2001 From: mingodad Date: Tue, 6 Jun 2023 14:13:10 +0200 Subject: [PATCH] Add an option to output profiling/coverage info (basically function calls count and clock_t time spent). There is an option to define how many samples to use with the definition of compile time macro "PROFILE_CALLS_SAMPLE" the default value is 10. The code is guarded by a compile time macro "CONFIG_PROFILE_CALLS", to build execute "make CONFIG_PROFILE_CALLS=1". When using the added option "-p" we can repeat it up to 3 times: - "-p" -> Only update calls count and omit functions with 0 calls - "-p -p" -> Update calls count and sampled time_spent and omit functions with 0 calls - "-p -p -p" -> Like the above but showing functions with 0 calls. The output format: =[ code_line call_count acumulated_time_spent average_time_spent function_name ] [454 2 1 6 xfillArr] --- Makefile | 4 ++++ qjs.c | 16 +++++++++++++++ quickjs.c | 59 +++++++++++++++++++++++++++++++++++++++++++++++++++++-- quickjs.h | 4 ++++ 4 files changed, 81 insertions(+), 2 deletions(-) diff --git a/Makefile b/Makefile index 49b1f6f..2c1c268 100644 --- a/Makefile +++ b/Makefile @@ -132,6 +132,10 @@ else LDEXPORT=-rdynamic endif +ifdef CONFIG_PROFILE_CALLS +CFLAGS+=-DCONFIG_PROFILE_CALLS +endif + PROGS=qjs$(EXE) qjsc$(EXE) run-test262 ifneq ($(CROSS_PREFIX),) QJSC_CC=gcc diff --git a/qjs.c b/qjs.c index d56b843..77946a3 100644 --- a/qjs.c +++ b/qjs.c @@ -297,6 +297,9 @@ void help(void) #endif "-T --trace trace memory allocation\n" "-d --dump dump the memory usage stats\n" +#ifdef CONFIG_PROFILE_CALLS + "-p --profile dump the profiling stats\n" +#endif " --memory-limit n limit the memory usage to 'n' bytes\n" " --stack-size n limit the stack size to 'n' bytes\n" " --unhandled-rejection dump unhandled promise rejections\n" @@ -314,6 +317,9 @@ int main(int argc, char **argv) int interactive = 0; int dump_memory = 0; int trace_memory = 0; +#ifdef CONFIG_PROFILE_CALLS + int profile_calls = 0; +#endif int empty_run = 0; int module = -1; int load_std = 0; @@ -407,6 +413,12 @@ int main(int argc, char **argv) trace_memory++; continue; } +#ifdef CONFIG_PROFILE_CALLS + if (opt == 'p' || !strcmp(longopt, "profile")) { + ++profile_calls; + continue; + } +#endif if (!strcmp(longopt, "std")) { load_std = 1; continue; @@ -467,6 +479,10 @@ int main(int argc, char **argv) fprintf(stderr, "qjs: cannot allocate JS runtime\n"); exit(2); } +#ifdef CONFIG_PROFILE_CALLS + if(profile_calls) + JS_EnableProfileCalls(rt, profile_calls); +#endif if (memory_limit != 0) JS_SetMemoryLimit(rt, memory_limit); if (stack_size != 0) diff --git a/quickjs.c b/quickjs.c index 7916013..23e9a53 100644 --- a/quickjs.c +++ b/quickjs.c @@ -304,6 +304,12 @@ struct JSRuntime { JSNumericOperations bigfloat_ops; JSNumericOperations bigdecimal_ops; uint32_t operator_count; +#endif +#ifdef CONFIG_PROFILE_CALLS + // is_profile_calls_enabled = 1 -> only call_count > 0 + // is_profile_calls_enabled = 2 -> only call_count > 0 and time_spent + // is_profile_calls_enabled = 3 -> all call_count and time_spent + uint32_t is_profile_calls_enabled; #endif void *user_opaque; }; @@ -620,6 +626,14 @@ typedef struct JSFunctionBytecode { int pc2line_len; uint8_t *pc2line_buf; char *source; +#ifdef CONFIG_PROFILE_CALLS +#ifndef PROFILE_CALLS_SAMPLE +#define PROFILE_CALLS_SAMPLE 10 +#endif + size_t call_count; + clock_t time_spent; + size_t time_spent_count; +#endif } debug; } JSFunctionBytecode; @@ -3046,7 +3060,11 @@ static const char *JS_AtomGetStrRT(JSRuntime *rt, char *buf, int buf_size, q = buf; p = rt->atom_array[atom]; +#ifdef CONFIG_PROFILE_CALLS + if(atom_is_free(p)) return "<:isGone:>"; +#else assert(!atom_is_free(p)); +#endif str = p; if (str) { if (!str->is_wide_char) { @@ -5501,8 +5519,17 @@ void __JS_FreeValueRT(JSRuntime *rt, JSValue v) } } break; - case JS_TAG_OBJECT: case JS_TAG_FUNCTION_BYTECODE: +#ifdef CONFIG_PROFILE_CALLS + if(rt->is_profile_calls_enabled) { + JSFunctionBytecode *b = JS_VALUE_GET_PTR(v); + if(b->debug.call_count || rt->is_profile_calls_enabled > 2) { + char buf[ATOM_GET_STR_BUF_SIZE]; + fprintf(stderr, "[%d\t%zu\t%zu\t%zu\t%s]\n", b->debug.line_num, b->debug.call_count, b->debug.time_spent_count, b->debug.time_spent, JS_AtomGetStrRT(rt, buf, sizeof(buf), b->func_name)); + } + } +#endif + case JS_TAG_OBJECT: { JSGCObjectHeader *p = JS_VALUE_GET_PTR(v); if (rt->gc_phase != JS_GC_PHASE_REMOVE_CYCLES) { @@ -5817,6 +5844,12 @@ BOOL JS_IsLiveObject(JSRuntime *rt, JSValueConst obj) p = JS_VALUE_GET_OBJ(obj); return !p->free_mark; } +#ifdef CONFIG_PROFILE_CALLS +void JS_EnableProfileCalls(JSRuntime *rt, uint32_t enable) +{ + rt->is_profile_calls_enabled = enable; +} +#endif /* Compute memory used by various object types */ /* XXX: poor man's approach to handling multiply referenced objects */ @@ -16209,6 +16242,11 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj, JSValue *local_buf, *stack_buf, *var_buf, *arg_buf, *sp, ret_val, *pval; JSVarRef **var_refs; size_t alloca_size; +#ifdef CONFIG_PROFILE_CALLS + //size_t this_call_count; + clock_t JS_CallInternal_start = 0; + int use_time_spent = 0; +#endif #if !DIRECT_DISPATCH #define SWITCH(pc) switch (opcode = *pc++) @@ -16272,7 +16310,17 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj, (JSValueConst *)argv, flags); } b = p->u.func.function_bytecode; - +#ifdef CONFIG_PROFILE_CALLS + if(rt->is_profile_calls_enabled) { + if(rt->is_profile_calls_enabled > 1) { + use_time_spent = b->debug.call_count % PROFILE_CALLS_SAMPLE; + if(use_time_spent == 0) { + JS_CallInternal_start = clock(); + } + } + ++b->debug.call_count; + } +#endif if (unlikely(argc < b->arg_count || (flags & JS_CALL_FLAG_COPY_ARGV))) { arg_allocated_size = b->arg_count; } else { @@ -18706,6 +18754,13 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj, } } rt->current_stack_frame = sf->prev_frame; +#ifdef CONFIG_PROFILE_CALLS + if(rt->is_profile_calls_enabled > 1 && (use_time_spent == 0)) { + clock_t JS_CallInternal_end = clock(); + b->debug.time_spent += JS_CallInternal_end-JS_CallInternal_start; + ++b->debug.time_spent_count; + } +#endif return ret_val; } diff --git a/quickjs.h b/quickjs.h index d4a5cd3..4cad840 100644 --- a/quickjs.h +++ b/quickjs.h @@ -346,6 +346,10 @@ typedef void JS_MarkFunc(JSRuntime *rt, JSGCObjectHeader *gp); void JS_MarkValue(JSRuntime *rt, JSValueConst val, JS_MarkFunc *mark_func); void JS_RunGC(JSRuntime *rt); JS_BOOL JS_IsLiveObject(JSRuntime *rt, JSValueConst obj); +#ifdef CONFIG_PROFILE_CALLS +void JS_EnableProfileCalls(JSRuntime *rt, uint32_t enable); +#endif + JSContext *JS_NewContext(JSRuntime *rt); void JS_FreeContext(JSContext *s);