Implements profiling support by hooking into the function execution. qjs outputs chrome devtools-compatible profiling data

This commit is contained in:
Ruben 2024-11-24 00:18:38 +01:00
parent 6e2e68fd08
commit cae84d06d5
4 changed files with 235 additions and 2 deletions

View File

@ -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

77
qjs.c
View File

@ -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 : "<anonymous>";
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 : "<anonymous>";
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];

129
quickjs.c
View File

@ -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 <unknown>
StringBuffer sb;
char prefix[] = "<unknown>.";
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;
}

View File

@ -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);