From 3e6632807a27b04b7a464ff9031fd91ebb3a4d05 Mon Sep 17 00:00:00 2001 From: "K. Lange" Date: Wed, 6 Mar 2024 20:16:48 +0900 Subject: [PATCH] New callgrind and watchdog tools --- tools/callgrind.c | 330 ++++++++++++++++++++++++++++++++++++++++++++++ tools/common.h | 57 ++++++++ tools/watchdog.c | 71 ++++++++++ 3 files changed, 458 insertions(+) create mode 100644 tools/callgrind.c create mode 100644 tools/common.h create mode 100644 tools/watchdog.c diff --git a/tools/callgrind.c b/tools/callgrind.c new file mode 100644 index 0000000..35ae142 --- /dev/null +++ b/tools/callgrind.c @@ -0,0 +1,330 @@ +/** + * @brief Function call tracing tool + * @file tools/callgrind.c + * @author K. Lange + * + * Generates cachegrind/callgrind trace files while running scripts. + * + * Traces include per-line instruction execution counts and per-function + * (as well as per-call) wall clock timing information. + * + * Collecting instruction counts can be quite slow, so expect this to + * increase runtime by as much as ~25×, depending on the code. + */ +#include +#include +#include +#include +#include +#include +#include +#include + +#include "common.h" + +extern KrkValue krk_operator_add (KrkValue a, KrkValue b); +extern KrkValue krk_operator_sub (KrkValue a, KrkValue b); + +static int usage(char * argv[]) { + fprintf(stderr, "usage: %s [FILE] [args...]\n", argv[0]); + return 1; +} + +static KrkValue lineCache; /* {sourceCO: {line: count}} */ +static KrkValue callCache; /* {sourceCO: {(codeobject,targetLine,sourceLine): [calls,instructions,time]}} */ +static KrkValue timeCache; /* {sourceCO: time} */ + +static size_t lastFrameCount = 0; /* Previously seen frame count, to track function entry/exit */ +static size_t instrCounter = 0; /* Total counter of executed instructions */ +static size_t functionsEntered = 0; /* Number of function entries seen */ + +/** + * @brief Calculate time difference as string. + * + * Calculates the number of nanoseconds since @p in_time and formats + * the result as a string which can then be parsed into a @c long. + * + * @param in_time Start time to calculate from. + * @param buf String buffer to write into. + */ +static void time_diff(struct timespec in_time, char * buf) { + struct timespec outTime, diff; + clock_gettime(CLOCK_MONOTONIC, &outTime); + diff.tv_sec = outTime.tv_sec - in_time.tv_sec; + diff.tv_nsec = outTime.tv_nsec - in_time.tv_nsec; + if (diff.tv_nsec < 0) { + diff.tv_sec--; + diff.tv_nsec += 1000000000L; + } + snprintf(buf,50,"%lld%.9ld", (long long)diff.tv_sec, diff.tv_nsec); +} + +struct FrameMetadata { + KrkCodeObject * target_obj; /* Function being entered */ + size_t target_line; /* First line seen in the entered function */ + size_t count; /* Instruction count on entry */ + size_t source_line; /* Line we came from in the caller */ + KrkCodeObject * source_obj; /* Function we came from in the caller */ + struct timespec in_time; /* Time of frame entry */ +}; + +static struct FrameMetadata frameMetadata[KRK_CALL_FRAMES_MAX]; + +int krk_callgrind_debuggerHook(KrkCallFrame * frame) { + instrCounter++; + + if (krk_currentThread.frameCount != lastFrameCount) { + if (krk_currentThread.frameCount > lastFrameCount) { + /* When we detect function entry, record details of the function being called + * and what called in, and record the current time. */ + KrkCallFrame * prev = lastFrameCount ? &krk_currentThread.frames[lastFrameCount-1] : NULL; + frameMetadata[lastFrameCount].target_obj = frame->closure->function; + frameMetadata[lastFrameCount].target_line = krk_lineNumber(&frame->closure->function->chunk, frame->ip - frame->closure->function->chunk.code); + frameMetadata[lastFrameCount].count = instrCounter; + frameMetadata[lastFrameCount].source_obj = prev ? prev->closure->function : NULL; + frameMetadata[lastFrameCount].source_line = prev ? krk_lineNumber(&prev->closure->function->chunk, prev->ip - 1 - prev->closure->function->chunk.code) : 0; + clock_gettime(CLOCK_MONOTONIC, &frameMetadata[lastFrameCount].in_time); + functionsEntered++; + } else { + size_t procFrame = lastFrameCount - 1; + while (procFrame >= krk_currentThread.frameCount) { + if (procFrame == 0) { + /* This is the outermost call, eg. , returning to the interpreter. We still want to make + * sure we collect the time spent in the call and add it to the time for the function, so that + * the time spent inside other function calls is subtracted to get the time spent actually + * executing code in the module. */ + char tmp[50]; + time_diff(frameMetadata[procFrame].in_time, tmp); + KrkValue diffTime = krk_parse_int(tmp,strlen(tmp),10); + krk_push(diffTime); + KrkValue totalTime = INTEGER_VAL(0); + krk_tableGet(AS_DICT(timeCache),OBJECT_VAL(frameMetadata[procFrame].target_obj),&totalTime); + krk_push(krk_operator_add(totalTime,diffTime)); + krk_tableSet(AS_DICT(timeCache),OBJECT_VAL(frameMetadata[procFrame].target_obj),krk_peek(0)); + krk_pop(); + krk_pop(); + break; + } + + /* Set up dict for call mappings */ + KrkValue ndict = NONE_VAL(); + if (!krk_tableGet(AS_DICT(callCache),OBJECT_VAL(frameMetadata[procFrame].source_obj),&ndict)) { + ndict = krk_dict_of(0,NULL,0); + krk_push(ndict); + krk_tableSet(AS_DICT(callCache),OBJECT_VAL(frameMetadata[procFrame].source_obj),ndict); + krk_pop(); + } + + KrkTuple * t = krk_newTuple(3); + krk_push(OBJECT_VAL(t)); + + /* Target code object */ + t->values.values[t->values.count++] = OBJECT_VAL(frameMetadata[procFrame].target_obj); + + /* Target and source lines */ + t->values.values[t->values.count++] = INTEGER_VAL(frameMetadata[procFrame].target_line); + t->values.values[t->values.count++] = INTEGER_VAL(frameMetadata[procFrame].source_line); + + KrkValue nlist = NONE_VAL(); + if (!krk_tableGet(AS_DICT(ndict),krk_peek(0),&nlist)) { + nlist = krk_list_of(3,(const KrkValue[]){INTEGER_VAL(0),INTEGER_VAL(0),INTEGER_VAL(0)},0); + krk_push(nlist); + krk_tableSet(AS_DICT(ndict),krk_peek(1),krk_peek(0)); + krk_pop(); + } + krk_pop(); /* tuple */ + + /* totalCalls += 1 */ + krk_push(krk_operator_add(AS_LIST(nlist)->values[0],INTEGER_VAL(1))); + AS_LIST(nlist)->values[0] = krk_pop(); + + /* totalCosts += last cost */ + char tmp[50]; + snprintf(tmp,50,"%zu", instrCounter - frameMetadata[procFrame].count); + KrkValue diffCount = krk_parse_int(tmp,strlen(tmp),10); + krk_push(diffCount); + krk_push(krk_operator_add(AS_LIST(nlist)->values[1],diffCount)); + AS_LIST(nlist)->values[1] = krk_pop(); + krk_pop(); /* diffCount */ + + time_diff(frameMetadata[procFrame].in_time, tmp); /* Time for this call */ + KrkValue diffTime = krk_parse_int(tmp,strlen(tmp),10); + krk_push(diffTime); + krk_push(krk_operator_add(AS_LIST(nlist)->values[2],diffTime)); + AS_LIST(nlist)->values[2] = krk_pop(); + + KrkValue myTime = INTEGER_VAL(0); /* Time spent here */ + krk_tableGet(AS_DICT(timeCache),OBJECT_VAL(frameMetadata[procFrame].target_obj),&myTime); + krk_push(krk_operator_add(myTime,diffTime)); + krk_tableSet(AS_DICT(timeCache),OBJECT_VAL(frameMetadata[procFrame].target_obj),krk_peek(0)); + krk_pop(); /* myTime + diffTime */ + + KrkValue parentTime = INTEGER_VAL(0); /* Was not spent there */ + krk_tableGet(AS_DICT(timeCache),OBJECT_VAL(frameMetadata[procFrame].source_obj),&parentTime); + krk_push(krk_operator_sub(parentTime,diffTime)); + krk_tableSet(AS_DICT(timeCache),OBJECT_VAL(frameMetadata[procFrame].source_obj),krk_peek(0)); + krk_pop(); /* parentTime - diffTime */ + + krk_pop(); /* diffTime */ + + memset(&frameMetadata[procFrame], 0, sizeof(struct FrameMetadata)); + procFrame--; + } + } + lastFrameCount = krk_currentThread.frameCount; + } + + if (!frame) return KRK_DEBUGGER_QUIT; + + /* Set up dict for instruction counts */ + KrkValue ndict = NONE_VAL(); + if (!krk_tableGet(AS_DICT(lineCache),OBJECT_VAL(frame->closure->function),&ndict)) { + ndict = krk_dict_of(0,NULL,0); + krk_push(ndict); + krk_tableSet(AS_DICT(lineCache),OBJECT_VAL(frame->closure->function),ndict); + krk_pop(); + } + + KrkValue lineNumber = INTEGER_VAL(krk_lineNumber(&frame->closure->function->chunk, frame->ip - frame->closure->function->chunk.code)); + + /* Add one to instruction count for this line */ + KrkValue count = INTEGER_VAL(0); + krk_tableGet(AS_DICT(ndict), lineNumber, &count); + krk_push(krk_operator_add(count, INTEGER_VAL(1))); + krk_tableSet(AS_DICT(ndict), lineNumber, krk_peek(0)); + krk_pop(); /* count + 1 */ + + return KRK_DEBUGGER_STEP; +} + + +int main(int argc, char *argv[]) { + char outfile[1024]; + snprintf(outfile,1024,"callgrind.out.%d",getpid()); + + int opt; + while ((opt = getopt(argc, argv, "+:f:-:")) != -1) { + switch (opt) { + case 'f': + snprintf(outfile,1024,"%s", optarg); + break; + case '?': + if (optopt != '-') { + fprintf(stderr, "%s: unrocognized option '%c'\n", argv[0], optopt); + return 1; + } + optarg = argv[optind]+1; + /* fall through */ + case '-': + if (!strcmp(optarg,"help")) { + } else { + fprintf(stderr, "%s: unrecognized option: '--%s'\n", argv[0], optarg); + return 1; + } + } + } + if (optind == argc) { + return usage(argv); + } + + findInterpreter(argv); + krk_initVM(KRK_THREAD_SINGLE_STEP); + krk_debug_registerCallback(krk_callgrind_debuggerHook); + addArgs(argc,argv); + + krk_startModule("__main__"); + + lineCache = krk_dict_of(0,NULL,0); + krk_attachNamedValue(&krk_currentThread.module->fields,"__line_cache__",lineCache); + callCache = krk_dict_of(0,NULL,0); + krk_attachNamedValue(&krk_currentThread.module->fields,"__call_cache__",callCache); + timeCache = krk_dict_of(0,NULL,0); + krk_attachNamedValue(&krk_currentThread.module->fields,"__time_cache__",timeCache); + + krk_runfile(argv[optind],argv[optind]); + + if (krk_currentThread.flags & KRK_THREAD_HAS_EXCEPTION) { + krk_currentThread.flags &= ~(KRK_THREAD_HAS_EXCEPTION); + fprintf(stderr, "== Executed ended by exception ==\n"); + } else { + fprintf(stderr, "== Execution completed ==\n"); + } + krk_callgrind_debuggerHook(NULL); + + fprintf(stderr, "%10zu total instruction%s\n", instrCounter, (instrCounter != 1) ? "s" : ""); + fprintf(stderr, "%10zu function%s calls\n", functionsEntered, (functionsEntered != 1) ? "s" : ""); + + FILE * f = fopen(outfile,"w"); + if (!f) { + fprintf(stderr, "%s: %s: %s\n", argv[0], outfile, strerror(errno)); + return 1; + } + + fprintf(f,"# callgrind format\n"); + fprintf(f,"creator: Kuroko\n"); + fprintf(f,"positions: line\n"); + fprintf(f,"events: instructions nanoseconds\n"); + fprintf(f,"cmd: %s %s\n", argv[0], argv[optind]); + fprintf(f,"summary: %zu ", instrCounter); + char tmp[50]; + time_diff(frameMetadata[0].in_time, tmp); + fprintf(f,"%s\n", tmp); + + + for (size_t j = 0; j < AS_DICT(lineCache)->used; ++j) { + if (IS_KWARGS(AS_DICT(lineCache)->entries[j].key)) continue; + + KrkCodeObject * function = (void*)AS_OBJECT(AS_DICT(lineCache)->entries[j].key); + KrkValue ndict = AS_DICT(lineCache)->entries[j].value; + + fprintf(f,"fl=%s\n", function->chunk.filename->chars); + fprintf(f,"fn=%s@%p\n", function->qualname ? function->qualname->chars : function->name->chars, (void*)function); + + KrkValue timeValue = NONE_VAL(); + krk_tableGet(AS_DICT(timeCache), OBJECT_VAL(function), &timeValue); + if (!IS_NONE(timeValue)) { + fprintf(f,"%zu ", (size_t)krk_lineNumber(&function->chunk, 0)); + struct StringBuilder sb = {0}; + krk_pushStringBuilderFormat(&sb, "0 %R\n", timeValue); + fprintf(f,"%.*s", (int)sb.length, sb.bytes); + krk_discardStringBuilder(&sb); + } + + for (size_t k = 0; k < AS_DICT(ndict)->used; ++k) { + if (IS_KWARGS(AS_DICT(ndict)->entries[k].key)) continue; + struct StringBuilder sb = {0}; + krk_pushStringBuilderFormat(&sb, "%R %R 0\n", AS_DICT(ndict)->entries[k].key, AS_DICT(ndict)->entries[k].value); + fprintf(f,"%.*s", (int)sb.length, sb.bytes); + krk_discardStringBuilder(&sb); + } + + KrkValue cdict = NONE_VAL(); + krk_tableGet(AS_DICT(callCache), OBJECT_VAL(function), &cdict); + if (!IS_NONE(cdict)) { + for (size_t l = 0; l < AS_DICT(cdict)->used; ++l) { + if (IS_KWARGS(AS_DICT(cdict)->entries[l].key)) continue; + + KrkCodeObject * target = (void*)AS_OBJECT(AS_TUPLE(AS_DICT(cdict)->entries[l].key)->values.values[0]); + KrkValue targetLine = AS_TUPLE(AS_DICT(cdict)->entries[l].key)->values.values[1]; + KrkValue sourceLine = AS_TUPLE(AS_DICT(cdict)->entries[l].key)->values.values[2]; + KrkValue totalCalls = AS_LIST(AS_DICT(cdict)->entries[l].value)->values[0]; + KrkValue totalCost = AS_LIST(AS_DICT(cdict)->entries[l].value)->values[1]; + KrkValue totalTime = AS_LIST(AS_DICT(cdict)->entries[l].value)->values[2]; + + fprintf(f,"cfi=%s\n", target->chunk.filename->chars); + fprintf(f,"cfn=%s@%p\n", target->qualname ? target->qualname->chars : target->name->chars, (void*)target); + + struct StringBuilder sb = {0}; + krk_pushStringBuilderFormat(&sb, "calls=%R %R\n%R %R %R\n", totalCalls, targetLine, sourceLine, totalCost, totalTime); + fprintf(f,"%.*s",(int)sb.length,sb.bytes); + krk_discardStringBuilder(&sb); + } + } + } + + fclose(f); + + krk_freeVM(); + return 0; +} + diff --git a/tools/common.h b/tools/common.h new file mode 100644 index 0000000..1ddfb46 --- /dev/null +++ b/tools/common.h @@ -0,0 +1,57 @@ +#include +#include +#include + +/* Copied from src/kuroko.c */ +static void findInterpreter(char * argv[]) { +#ifdef _WIN32 + vm.binpath = strdup(_pgmptr); +#else + /* Try asking /proc */ + char tmp[4096]; + char * binpath = realpath("/proc/self/exe", NULL); + if (!binpath || (access(binpath, X_OK) != 0)) { + if (binpath) { + free(binpath); + binpath = NULL; + } + if (strchr(argv[0], '/')) { + binpath = realpath(argv[0], NULL); + } else { + /* Search PATH for argv[0] */ + char * p = getenv("PATH"); + if (!p) return; + char * _path = strdup(p); + char * path = _path; + while (path) { + char * next = strchr(path,':'); + if (next) *next++ = '\0'; + + snprintf(tmp, 4096, "%s/%s", path, argv[0]); + if (access(tmp, X_OK) == 0) { + binpath = strdup(tmp); + break; + } + path = next; + } + free(_path); + } + } + if (binpath) { + vm.binpath = binpath; + } /* Else, give up at this point and just don't attach it at all. */ +#endif +} + +/* Collect arguments for script, also copied from src/kuroko.c */ +static void addArgs(int argc, char * argv[]) { + for (int arg = optind; arg < argc; ++arg) { + krk_push(OBJECT_VAL(krk_copyString(argv[arg],strlen(argv[arg])))); + } + KrkValue argList = krk_callNativeOnStack(argc - optind + (optind == argc), &krk_currentThread.stackTop[-(argc - optind + (optind == argc))], 0, krk_list_of); + krk_push(argList); + krk_attachNamedValue(&vm.system->fields, "argv", argList); + krk_pop(); + for (int arg = optind; arg < argc + (optind == argc); ++arg) krk_pop(); +} + diff --git a/tools/watchdog.c b/tools/watchdog.c new file mode 100644 index 0000000..a29c15c --- /dev/null +++ b/tools/watchdog.c @@ -0,0 +1,71 @@ +#include +#include +#include +#include +#include +#include +#include +#include + +#include "common.h" + +static int usage(char * argv[]) { + fprintf(stderr, "usage: %s [-s count] [FILE] [args...]\n", argv[0]); + return 1; +} + +static size_t instrCounter = 0; /* Total counter of executed instructions */ +static size_t stopAt = 500000; + +int krk_callgrind_debuggerHook(KrkCallFrame * frame) { + instrCounter++; + if (instrCounter < stopAt) return KRK_DEBUGGER_STEP; + if (instrCounter == stopAt) { + krk_runtimeError(vm.exceptions->baseException, "Watchdog counter expired."); + } + return KRK_DEBUGGER_CONTINUE; +} + + +int main(int argc, char *argv[]) { + int opt; + while ((opt = getopt(argc, argv, "+:s:-:")) != -1) { + switch (opt) { + case 's': + stopAt = strtoul(optarg,NULL,10); + break; + case '?': + if (optopt != '-') { + fprintf(stderr, "%s: unrocognized option '%c'\n", argv[0], optopt); + return 1; + } + optarg = argv[optind]+1; + /* fall through */ + case '-': + if (!strcmp(optarg,"help")) { + } else { + fprintf(stderr, "%s: unrecognized option: '--%s'\n", argv[0], optarg); + return 1; + } + } + } + + if (optind == argc) { + return usage(argv); + } + + findInterpreter(argv); + krk_initVM(KRK_THREAD_SINGLE_STEP); + krk_debug_registerCallback(krk_callgrind_debuggerHook); + addArgs(argc,argv); + + krk_startModule("__main__"); + krk_runfile(argv[optind],argv[optind]); + + fprintf(stderr, "%zu total instructions\n", instrCounter); + + krk_freeVM(); + return 0; +} + +