From cae84d06d516a4213852b732c4aa50c89de714e2 Mon Sep 17 00:00:00 2001 From: Ruben Date: Sun, 24 Nov 2024 00:18:38 +0100 Subject: [PATCH] Implements profiling support by hooking into the function execution. qjs outputs chrome devtools-compatible profiling data --- Makefile | 6 +++ qjs.c | 77 ++++++++++++++++++++++++++++++++ quickjs.c | 129 +++++++++++++++++++++++++++++++++++++++++++++++++++++- quickjs.h | 25 +++++++++++ 4 files changed, 235 insertions(+), 2 deletions(-) diff --git a/Makefile b/Makefile index cf88a72..58727fe 100644 --- a/Makefile +++ b/Makefile @@ -53,6 +53,9 @@ PREFIX?=/usr/local # include the code for BigFloat/BigDecimal and math mode CONFIG_BIGNUM=y +# Include code for profiling individual function calls. +# qjs will produce a file compatible with chrome devtools and other tools. +# CONFIG_PROFILE_CALLS=y OBJDIR=.obj @@ -148,6 +151,9 @@ ifeq ($(shell $(CC) -o /dev/null compat/test-closefrom.c 2>/dev/null && echo 1), DEFINES+=-DHAVE_CLOSEFROM endif endif +ifdef CONFIG_PROFILE_CALLS +DEFINES+=-DCONFIG_PROFILE_CALLS +endif CFLAGS+=$(DEFINES) CFLAGS_DEBUG=$(CFLAGS) -O0 diff --git a/qjs.c b/qjs.c index 7103e11..1bfb522 100644 --- a/qjs.c +++ b/qjs.c @@ -289,6 +289,10 @@ void help(void) #endif "-T --trace trace memory allocation\n" "-d --dump dump the memory usage stats\n" +#ifdef CONFIG_PROFILE_CALLS + "-p --profile FILE dump the profiling stats to FILENAME in a format that can be open in chromium devtools\n" + " --profile-sampling n collect function calls every 1/n times. Defaults to 1 (i.e. every call)\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" @@ -296,6 +300,39 @@ void help(void) exit(1); } +#ifdef CONFIG_PROFILE_CALLS +void profile_function_start(JSContext *ctx, JSAtom func, JSAtom filename, void *opaque) { + const char* func_str = JS_AtomToCString(ctx, func); + const char *func_str2 = func_str[0] ? func_str : ""; + FILE *logfile = (FILE *)opaque; + // Format documented here: + // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.yr4qxyxotyw + fprintf(logfile, "{" + "\"name\": \"%s\"," + "\"cat\": \"js\"," + "\"ph\": \"B\"," + "\"ts\": %ld," + "\"pid\": 1," + "\"tid\": 1" + "},\n", func_str2, clock()); + JS_FreeCString(ctx, func_str); +} +void profile_function_end(JSContext *ctx, JSAtom func, JSAtom filename, void *opaque) { + const char* func_str = JS_AtomToCString(ctx, func); + const char *func_str2 = func_str[0] ? func_str : ""; + FILE *logfile = (FILE *)opaque; + fprintf(logfile, "{" + "\"name\": \"%s\"," + "\"cat\": \"js\"," + "\"ph\": \"E\"," + "\"ts\": %ld," + "\"pid\": 1," + "\"tid\": 1" + "},\n", func_str2, clock()); + JS_FreeCString(ctx, func_str); +} +#endif + int main(int argc, char **argv) { JSRuntime *rt; @@ -306,6 +343,10 @@ int main(int argc, char **argv) int interactive = 0; int dump_memory = 0; int trace_memory = 0; +#ifdef CONFIG_PROFILE_CALLS + FILE *profile_file = NULL; + uint32_t profile_sampling = 1; +#endif int empty_run = 0; int module = -1; int load_std = 0; @@ -399,6 +440,29 @@ int main(int argc, char **argv) trace_memory++; continue; } +#ifdef CONFIG_PROFILE_CALLS + if (opt == 'p' || !strcmp(longopt, "profile")) { + if (*arg) { + profile_file = fopen(arg, "w"); + break; + } + if (optind < argc) { + profile_file = fopen(argv[optind++], "w"); + break; + } + fprintf(stderr, "qjs: missing filename for -p\n"); + exit(1); + continue; + } + if (!strcmp(longopt, "profile-sampling")) { + if (optind >= argc) { + fprintf(stderr, "expecting profile sampling"); + exit(1); + } + profile_sampling = (uint32_t)strtod(argv[optind++], NULL); + continue; + } +#endif if (!strcmp(longopt, "std")) { load_std = 1; continue; @@ -461,6 +525,12 @@ int main(int argc, char **argv) fprintf(stderr, "qjs: cannot allocate JS runtime\n"); exit(2); } +#ifdef CONFIG_PROFILE_CALLS + if(profile_file) { + JS_EnableProfileCalls(rt, profile_function_start, profile_function_end, profile_sampling, profile_file); + fprintf(profile_file, "{\"traceEvents\": ["); + } +#endif if (memory_limit != 0) JS_SetMemoryLimit(rt, memory_limit); if (stack_size != 0) @@ -530,6 +600,13 @@ int main(int argc, char **argv) js_std_free_handlers(rt); JS_FreeContext(ctx); JS_FreeRuntime(rt); +#ifdef CONFIG_PROFILE_CALLS + if(profile_file) { + // Inject an instant event at the end just to make sure it's valid JSON. + fprintf(profile_file, R"({"name": "end", "ph": "I", "ts": %ld, "pid": 1, "tid": 1, "s": "g"}]})", clock()); + fclose(profile_file); + } +#endif if (empty_run && dump_memory) { clock_t t[5]; diff --git a/quickjs.c b/quickjs.c index 642ae34..bda8552 100644 --- a/quickjs.c +++ b/quickjs.c @@ -302,6 +302,13 @@ struct JSRuntime { JSNumericOperations bigfloat_ops; JSNumericOperations bigdecimal_ops; uint32_t operator_count; +#endif +#ifdef CONFIG_PROFILE_CALLS + ProfileEventHandler *profile_function_start; + ProfileEventHandler *profile_function_end; + void *profile_opaque; + uint32_t profile_sampling; + uint32_t profile_sample_count; #endif void *user_opaque; }; @@ -621,6 +628,10 @@ typedef struct JSFunctionBytecode { int pc2line_len; uint8_t *pc2line_buf; char *source; +#ifdef CONFIG_PROFILE_CALLS + /* Class.function or Object.function or just function */ + JSAtom full_func_name_cache; +#endif } debug; } JSFunctionBytecode; @@ -5546,8 +5557,17 @@ void __JS_FreeValueRT(JSRuntime *rt, JSValue v) } } break; - case JS_TAG_OBJECT: case JS_TAG_FUNCTION_BYTECODE: +#ifdef CONFIG_PROFILE_CALLS + { + JSFunctionBytecode *b = JS_VALUE_GET_PTR(v); + // In STRICT js_mode, there is no "debug". + if (!(b->js_mode & JS_MODE_STRICT) && b->debug.full_func_name_cache != JS_ATOM_NULL) { + JS_FreeAtomRT(rt, b->debug.full_func_name_cache); + } + } +#endif + case JS_TAG_OBJECT: { JSGCObjectHeader *p = JS_VALUE_GET_PTR(v); if (rt->gc_phase != JS_GC_PHASE_REMOVE_CYCLES) { @@ -5881,6 +5901,20 @@ BOOL JS_IsLiveObject(JSRuntime *rt, JSValueConst obj) return !p->free_mark; } +void JS_EnableProfileCalls(JSRuntime *rt, ProfileEventHandler *on_start, ProfileEventHandler *on_end, uint32_t sampling, void *opaque_data) +{ +#ifdef CONFIG_PROFILE_CALLS + rt->profile_function_start = on_start; + rt->profile_function_end = on_end; + rt->profile_opaque = opaque_data; + // If sampling == 0, it's interpreted as "no sampling" which means we log 1/1 calls. + rt->profile_sampling = sampling > 0 ? sampling : 1; + rt->profile_sample_count = 0; +#else + fprintf(stderr, "QuickJS was not compiled with -DCONFIG_PROFILE_CALLS. Profiling is disabled."); +#endif +} + /* Compute memory used by various object types */ /* XXX: poor man's approach to handling multiply referenced objects */ typedef struct JSMemoryUsage_helper { @@ -6529,6 +6563,64 @@ static const char *get_func_name(JSContext *ctx, JSValueConst func) return JS_ToCString(ctx, val); } +/* Computes the full name of the function including the constructor of the + object it's being executed on, if any. For example, this may output + "MyClass.my_function" or if there is no "this", just "my_function". */ +static JSAtom get_full_func_name(JSContext *ctx, JSValueConst func, JSValueConst this_obj) +{ + JSAtom result_atom; + const char *func_str = get_func_name(ctx, func); + if (!func_str || func_str[0] == '\0') { + JS_FreeCString(ctx, func_str); + return JS_ATOM_NULL; + } + // If "this" isn't an object, return just the name. + if (JS_VALUE_GET_TAG(this_obj) != JS_TAG_OBJECT) { + result_atom = JS_NewAtom(ctx, func_str); + JS_FreeCString(ctx, func_str); + return result_atom; + } + + JSValue ctor = JS_GetProperty(ctx, this_obj, JS_ATOM_constructor); + const char *ctor_str = get_func_name(ctx, ctor); + size_t func_len = strlen(func_str); + JSValue result_val; + + if (ctor_str == NULL || ctor_str[0] == '\0') { + // Invalid constructor, use + StringBuffer sb; + char prefix[] = "."; + if (string_buffer_init2(ctx, &sb, sizeof(prefix) + func_len, 0)) { + JS_FreeCString(ctx, func_str); + JS_FreeCString(ctx, ctor_str); + JS_FreeValue(ctx, ctor); + return JS_ATOM_NULL; + } + string_buffer_write8(&sb, (const uint8_t *)prefix, sizeof(prefix)); + string_buffer_write8(&sb, (const uint8_t *)func_str, func_len); + result_val = string_buffer_end(&sb); + } else { + StringBuffer sb; + size_t ctor_len = strlen(ctor_str); + if (string_buffer_init2(ctx, &sb, ctor_len + 1 + func_len, 0)) { + JS_FreeCString(ctx, func_str); + JS_FreeCString(ctx, ctor_str); + JS_FreeValue(ctx, ctor); + return JS_ATOM_NULL; + } + string_buffer_write8(&sb, (const uint8_t *)ctor_str, ctor_len); + string_buffer_write8(&sb, (const uint8_t *)".", 1); + string_buffer_write8(&sb, (const uint8_t *)func_str, func_len); + result_val = string_buffer_end(&sb); + } + result_atom = JS_ValueToAtom(ctx, result_val); + JS_FreeValue(ctx, result_val); + JS_FreeCString(ctx, func_str); + JS_FreeCString(ctx, ctor_str); + JS_FreeValue(ctx, ctor); + return result_atom; +} + #define JS_BACKTRACE_FLAG_SKIP_FIRST_LEVEL (1 << 0) /* only taken into account if filename is provided */ #define JS_BACKTRACE_FLAG_SINGLE_LEVEL (1 << 1) @@ -16169,6 +16261,10 @@ 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 + JSAtom full_func_name = JS_ATOM_NULL; + const int must_sample = rt->profile_sampling && rt->profile_sample_count == 0; +#endif #if !DIRECT_DISPATCH #define SWITCH(pc) switch (opcode = *pc++) @@ -16232,7 +16328,22 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj, (JSValueConst *)argv, flags); } b = p->u.func.function_bytecode; - +#ifdef CONFIG_PROFILE_CALLS + if (unlikely(must_sample)) { + if (!(b->js_mode & JS_MODE_STRICT)) { + if (!b->debug.full_func_name_cache) { + b->debug.full_func_name_cache = get_full_func_name(caller_ctx, func_obj, this_obj); + } + full_func_name = b->debug.full_func_name_cache; + } else { + // Even if we can't cache it, we need to compute it to report the function execution. + full_func_name = get_full_func_name(caller_ctx, func_obj, this_obj); + } + if (likely(rt->profile_function_start)) { + rt->profile_function_start(caller_ctx, full_func_name, b->debug.filename, rt->profile_opaque); + } + } +#endif if (unlikely(argc < b->arg_count || (flags & JS_CALL_FLAG_COPY_ARGV))) { arg_allocated_size = b->arg_count; } else { @@ -18701,6 +18812,20 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj, } } rt->current_stack_frame = sf->prev_frame; +#ifdef CONFIG_PROFILE_CALLS + if (unlikely(must_sample)) { + if (likely(rt->profile_function_end)) { + rt->profile_function_end(caller_ctx, full_func_name, b->debug.filename, rt->profile_opaque); + } + if (b->js_mode & JS_MODE_STRICT) { + // If we weren't able to cache it, we have to free it right away (and sadly recreate it later). + JS_FreeAtom(caller_ctx, full_func_name); + } + } + if (unlikely(rt->profile_sampling)) { + rt->profile_sample_count = (rt->profile_sample_count + 1) % rt->profile_sampling; + } +#endif return ret_val; } diff --git a/quickjs.h b/quickjs.h index edc7b47..35508eb 100644 --- a/quickjs.h +++ b/quickjs.h @@ -350,6 +350,31 @@ void JS_MarkValue(JSRuntime *rt, JSValueConst val, JS_MarkFunc *mark_func); void JS_RunGC(JSRuntime *rt); JS_BOOL JS_IsLiveObject(JSRuntime *rt, JSValueConst obj); +/** + * Callback function type for handling JavaScript profiling events. + * + * @param func Function name as a JSAtom. May be in the format "Constructor.name" + * when the function is executed in a constructor's context (i.e., + * with 'this' binding) + * @param filename Name of the source file containing the function, as a JSAtom + * @param opaque_data User data that was originally passed to JS_EnableProfileCalls. + * Same value is provided to both start and end handlers + */ +typedef void ProfileEventHandler(JSContext *ctx, JSAtom func, JSAtom filename, void *opaque_data); +/** + * Enables function call profiling for the JavaScript runtime. + * + * NOTE: This function only works if QuickJS was compiled with -DCONFIG_PROFILE_CALLS flag. + * + * @param on_start Callback called when a function starts. + * @param on_end Callback called when a function ends. + * @param sampling Controls profiling frequency: only 1/sampling function calls are + * instrumented. Must be ≥ 1. Example: if sampling=4, only 25% of + * function calls will trigger the handlers. + * @param opaque_data Optional user data passed to both handlers. Can be NULL. + */ +void JS_EnableProfileCalls(JSRuntime *rt, ProfileEventHandler *on_start, ProfileEventHandler *on_end, uint32_t sampling, void *opaque_data); + JSContext *JS_NewContext(JSRuntime *rt); void JS_FreeContext(JSContext *s); JSContext *JS_DupContext(JSContext *ctx);