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]
This commit is contained in:
mingodad 2023-06-06 14:13:10 +02:00
parent 2788d71e82
commit 204ee9d17b
4 changed files with 81 additions and 2 deletions

View File

@ -132,6 +132,10 @@ else
LDEXPORT=-rdynamic LDEXPORT=-rdynamic
endif endif
ifdef CONFIG_PROFILE_CALLS
CFLAGS+=-DCONFIG_PROFILE_CALLS
endif
PROGS=qjs$(EXE) qjsc$(EXE) run-test262 PROGS=qjs$(EXE) qjsc$(EXE) run-test262
ifneq ($(CROSS_PREFIX),) ifneq ($(CROSS_PREFIX),)
QJSC_CC=gcc QJSC_CC=gcc

16
qjs.c
View File

@ -297,6 +297,9 @@ void help(void)
#endif #endif
"-T --trace trace memory allocation\n" "-T --trace trace memory allocation\n"
"-d --dump dump the memory usage stats\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" " --memory-limit n limit the memory usage to 'n' bytes\n"
" --stack-size n limit the stack size to 'n' bytes\n" " --stack-size n limit the stack size to 'n' bytes\n"
" --unhandled-rejection dump unhandled promise rejections\n" " --unhandled-rejection dump unhandled promise rejections\n"
@ -314,6 +317,9 @@ int main(int argc, char **argv)
int interactive = 0; int interactive = 0;
int dump_memory = 0; int dump_memory = 0;
int trace_memory = 0; int trace_memory = 0;
#ifdef CONFIG_PROFILE_CALLS
int profile_calls = 0;
#endif
int empty_run = 0; int empty_run = 0;
int module = -1; int module = -1;
int load_std = 0; int load_std = 0;
@ -407,6 +413,12 @@ int main(int argc, char **argv)
trace_memory++; trace_memory++;
continue; continue;
} }
#ifdef CONFIG_PROFILE_CALLS
if (opt == 'p' || !strcmp(longopt, "profile")) {
++profile_calls;
continue;
}
#endif
if (!strcmp(longopt, "std")) { if (!strcmp(longopt, "std")) {
load_std = 1; load_std = 1;
continue; continue;
@ -467,6 +479,10 @@ int main(int argc, char **argv)
fprintf(stderr, "qjs: cannot allocate JS runtime\n"); fprintf(stderr, "qjs: cannot allocate JS runtime\n");
exit(2); exit(2);
} }
#ifdef CONFIG_PROFILE_CALLS
if(profile_calls)
JS_EnableProfileCalls(rt, profile_calls);
#endif
if (memory_limit != 0) if (memory_limit != 0)
JS_SetMemoryLimit(rt, memory_limit); JS_SetMemoryLimit(rt, memory_limit);
if (stack_size != 0) if (stack_size != 0)

View File

@ -304,6 +304,12 @@ struct JSRuntime {
JSNumericOperations bigfloat_ops; JSNumericOperations bigfloat_ops;
JSNumericOperations bigdecimal_ops; JSNumericOperations bigdecimal_ops;
uint32_t operator_count; 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 #endif
void *user_opaque; void *user_opaque;
}; };
@ -620,6 +626,14 @@ typedef struct JSFunctionBytecode {
int pc2line_len; int pc2line_len;
uint8_t *pc2line_buf; uint8_t *pc2line_buf;
char *source; 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; } debug;
} JSFunctionBytecode; } JSFunctionBytecode;
@ -3046,7 +3060,11 @@ static const char *JS_AtomGetStrRT(JSRuntime *rt, char *buf, int buf_size,
q = buf; q = buf;
p = rt->atom_array[atom]; p = rt->atom_array[atom];
#ifdef CONFIG_PROFILE_CALLS
if(atom_is_free(p)) return "<:isGone:>";
#else
assert(!atom_is_free(p)); assert(!atom_is_free(p));
#endif
str = p; str = p;
if (str) { if (str) {
if (!str->is_wide_char) { if (!str->is_wide_char) {
@ -5501,8 +5519,17 @@ void __JS_FreeValueRT(JSRuntime *rt, JSValue v)
} }
} }
break; break;
case JS_TAG_OBJECT:
case JS_TAG_FUNCTION_BYTECODE: 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); JSGCObjectHeader *p = JS_VALUE_GET_PTR(v);
if (rt->gc_phase != JS_GC_PHASE_REMOVE_CYCLES) { 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); p = JS_VALUE_GET_OBJ(obj);
return !p->free_mark; 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 */ /* Compute memory used by various object types */
/* XXX: poor man's approach to handling multiply referenced objects */ /* 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; JSValue *local_buf, *stack_buf, *var_buf, *arg_buf, *sp, ret_val, *pval;
JSVarRef **var_refs; JSVarRef **var_refs;
size_t alloca_size; 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 #if !DIRECT_DISPATCH
#define SWITCH(pc) switch (opcode = *pc++) #define SWITCH(pc) switch (opcode = *pc++)
@ -16272,7 +16310,17 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj,
(JSValueConst *)argv, flags); (JSValueConst *)argv, flags);
} }
b = p->u.func.function_bytecode; 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))) { if (unlikely(argc < b->arg_count || (flags & JS_CALL_FLAG_COPY_ARGV))) {
arg_allocated_size = b->arg_count; arg_allocated_size = b->arg_count;
} else { } else {
@ -18706,6 +18754,13 @@ static JSValue JS_CallInternal(JSContext *caller_ctx, JSValueConst func_obj,
} }
} }
rt->current_stack_frame = sf->prev_frame; 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; return ret_val;
} }

View File

@ -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_MarkValue(JSRuntime *rt, JSValueConst val, JS_MarkFunc *mark_func);
void JS_RunGC(JSRuntime *rt); void JS_RunGC(JSRuntime *rt);
JS_BOOL JS_IsLiveObject(JSRuntime *rt, JSValueConst obj); 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); JSContext *JS_NewContext(JSRuntime *rt);
void JS_FreeContext(JSContext *s); void JS_FreeContext(JSContext *s);