New callgrind and watchdog tools
This commit is contained in:
K. Lange
parent
0eaa455fbe
commit
3e6632807a
330
tools/callgrind.c
Normal file
330
tools/callgrind.c
Normal file
@ -0,0 +1,330 @@
|
||||
/**
|
||||
* @brief Function call tracing tool
|
||||
* @file tools/callgrind.c
|
||||
* @author K. Lange <klange@toaruos.org>
|
||||
*
|
||||
* 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 <stdio.h>
|
||||
#include <unistd.h>
|
||||
#include <time.h>
|
||||
#include <errno.h>
|
||||
#include <kuroko/kuroko.h>
|
||||
#include <kuroko/vm.h>
|
||||
#include <kuroko/debug.h>
|
||||
#include <kuroko/util.h>
|
||||
|
||||
#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. <module>, 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;
|
||||
}
|
||||
|
||||
57
tools/common.h
Normal file
57
tools/common.h
Normal file
@ -0,0 +1,57 @@
|
||||
#include <stdlib.h>
|
||||
#include <kuroko/kuroko.h>
|
||||
#include <kuroko/vm.h>
|
||||
|
||||
/* 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();
|
||||
}
|
||||
|
||||
71
tools/watchdog.c
Normal file
71
tools/watchdog.c
Normal file
@ -0,0 +1,71 @@
|
||||
#include <stdio.h>
|
||||
#include <unistd.h>
|
||||
#include <time.h>
|
||||
#include <errno.h>
|
||||
#include <kuroko/kuroko.h>
|
||||
#include <kuroko/vm.h>
|
||||
#include <kuroko/debug.h>
|
||||
#include <kuroko/util.h>
|
||||
|
||||
#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;
|
||||
}
|
||||
|
||||
|
||||
Loading…
Reference in New Issue
Block a user