Trace function calls

This commit is contained in:
K. Lange 2021-03-23 17:44:39 +09:00
parent 6f92af28a2
commit 49066f7ae2
4 changed files with 103 additions and 1 deletions

49
modules/callgrind.krk Normal file
View File

@ -0,0 +1,49 @@
import kuroko
import fileio
def processFile(sourcePath, pid, cmd):
let funcs = {}
with fileio.open(sourcePath,'r') as f:
for line in f.readlines():
let callerFile, callerFunc, callerLine, calleeFile, calleeFunc, calleeLine, nsecs = line.split(' ')
nsecs = int(nsecs)
let data = funcs.get((callerFile,callerFunc),{})
let call = data.get((callerLine,calleeFile,calleeFunc,calleeLine),(0,0))
let out = (call[0] + 1, call[1] + nsecs)
data[callerLine,calleeFile,calleeFunc,calleeLine] = out
funcs[callerFile,callerFunc] = data
let called = funcs.get((calleeFile,calleeFunc),{})
let times = called.get(None,(1,0))
called[None] = (calleeLine, times[1] + nsecs)
funcs[calleeFile,calleeFunc] = called
with fileio.open(f'callgrind.out.{pid}','w') as out:
out.write('# callgrind format\n')
out.write('creator: Kuroko\n')
out.write('positions: line\n')
out.write('events: nanoseconds\n')
out.write(f'cmd: {cmd}\n\n')
for key, value in funcs.items():
let sFile, sFunc = key
out.write(f'fl={sFile}\n')
out.write(f'fn={sFunc}\n')
if sFunc != '(root)':
let startLine, totalNsecs = value[None]
for k, v in value.items():
if not k: continue
let sourceLine, file, func, destLine = k
let count, nsecs = v
totalNsecs -= nsecs
out.write(f'{startLine} {totalNsecs}\n')
for k, v in value.items():
if not k: continue
let sourceLine, file, func, destLine = k
let count, totalNsecs = v
if file != sFile: out.write(f'cfi={file}\n')
out.write(f'cfn={func}\n')
out.write(f'calls={count} {destLine}\n')
out.write(f'{sourceLine} {totalNsecs}\n')
out.write('\n')

View File

@ -33,6 +33,8 @@
#define PROMPT_MAIN ">>> "
#define PROMPT_BLOCK " > "
#define CALLGRIND_TMP_FILE "/tmp/kuroko.callgrind.tmp"
static int enableRline = 1;
static int exitRepl = 0;
static int pasteEnabled = 0;
@ -740,7 +742,7 @@ int main(int argc, char * argv[]) {
int flags = 0;
int moduleAsMain = 0;
int opt;
while ((opt = getopt(argc, argv, "+c:C:dgm:rstMSV-:")) != -1) {
while ((opt = getopt(argc, argv, "+c:C:dgm:rstTMSV-:")) != -1) {
switch (opt) {
case 'c':
return runString(argv, flags, optarg);
@ -763,6 +765,11 @@ int main(int argc, char * argv[]) {
/* Disassemble instructions as they are executed. */
flags |= KRK_THREAD_ENABLE_TRACING;
break;
case 'T': {
flags |= KRK_GLOBAL_CALLGRIND;
vm.callgrindFile = fopen(CALLGRIND_TMP_FILE,"w");
break;
}
case 'm':
moduleAsMain = 1;
optind--; /* to get us back to optarg */
@ -790,6 +797,7 @@ int main(int argc, char * argv[]) {
" -r Disable complex line editing in the REPL.\n"
" -s Debug output from the scanner/tokenizer.\n"
" -t Disassemble instructions as they are exceuted.\n"
" -T Write call trace file.\n"
" -C file Compile 'file', but do not execute it.\n"
" -M Print the default module import paths.\n"
" -S Enable single-step debugging.\n"
@ -1084,6 +1092,20 @@ _finishArgs:
if (IS_NONE(result) && krk_currentThread.flags & KRK_THREAD_HAS_EXCEPTION) result = INTEGER_VAL(1);
}
if (vm.globalFlags & KRK_GLOBAL_CALLGRIND) {
fclose(vm.callgrindFile);
vm.globalFlags &= ~(KRK_GLOBAL_CALLGRIND);
krk_resetStack();
krk_startModule("<callgrind>");
krk_attachNamedObject(&krk_currentThread.module->fields, "filename", (KrkObj*)S(CALLGRIND_TMP_FILE));
krk_interpret(
"from callgrind import processFile\n"
"import kuroko\n"
"import os\n"
"processFile(filename, os.getpid(), ' '.join(kuroko.argv))","<callgrind>");
}
krk_freeVM();
if (IS_INTEGER(result)) return AS_INTEGER(result);

View File

@ -8,6 +8,7 @@
*/
#include <stdarg.h>
#include <sys/types.h>
#include <sys/time.h>
#include "kuroko.h"
#include "value.h"
#include "table.h"
@ -47,6 +48,7 @@ typedef struct {
size_t slots; /**< Offset into the stack at which this function call's arguments begin */
size_t outSlots; /**< Offset into the stack at which stackTop will be reset upon return */
KrkTable * globals; /**< Pointer to the attribute table containing valud global vairables for this call */
struct timespec in_time;
} KrkCallFrame;
/**
@ -219,6 +221,7 @@ typedef struct KrkVM {
KrkObj** grayStack; /**< Scan list */
KrkThreadState * threads; /**< Invasive linked list of all VM threads. */
FILE * callgrindFile; /**< File to write unprocessed callgrind data to. */
} KrkVM;
/* Thread-specific flags */
@ -233,6 +236,7 @@ typedef struct KrkVM {
#define KRK_GLOBAL_ENABLE_STRESS_GC (1 << 8)
#define KRK_GLOBAL_GC_PAUSED (1 << 9)
#define KRK_GLOBAL_CLEAN_OUTPUT (1 << 10)
#define KRK_GLOBAL_CALLGRIND (1 << 11)
#ifdef ENABLE_THREADING
# define threadLocal __thread

View File

@ -78,6 +78,31 @@ __thread KrkThreadState krk_currentThread;
KrkThreadState krk_currentThread;
#endif
#ifdef ENABLE_TRACING
# define FRAME_IN(frame) if (vm.globalFlags & KRK_GLOBAL_CALLGRIND) { clock_gettime(CLOCK_MONOTONIC, &frame->in_time); }
# define FRAME_OUT(frame) \
if (vm.globalFlags & KRK_GLOBAL_CALLGRIND && !frame->closure->function->isGenerator) { \
KrkCallFrame * caller = krk_currentThread.frameCount > 1 ? &krk_currentThread.frames[krk_currentThread.frameCount-2] : NULL; \
struct timespec outTime; \
clock_gettime(CLOCK_MONOTONIC, &outTime); \
struct timespec diff; \
diff.tv_sec = outTime.tv_sec - frame->in_time.tv_sec; \
diff.tv_nsec = outTime.tv_nsec - frame->in_time.tv_nsec; \
if (diff.tv_nsec < 0) { diff.tv_sec--; diff.tv_nsec += 1000000000L; } \
fprintf(vm.callgrindFile, "%s %s %d %s %s %d %lld%.9ld\n", \
caller ? (caller->closure->function->chunk.filename->chars) : "stdin", \
caller ? (caller->closure->function->qualname ? caller->closure->function->qualname->chars : caller->closure->function->name->chars) : "(root)", \
caller ? ((int)krk_lineNumber(&caller->closure->function->chunk, caller->ip - caller->closure->function->chunk.code)) : 1, \
frame->closure->function->chunk.filename->chars, \
frame->closure->function->qualname ? frame->closure->function->qualname->chars : frame->closure->function->name->chars, \
(int)krk_lineNumber(&frame->closure->function->chunk, 0), \
(long long)diff.tv_sec, diff.tv_nsec); \
}
#else
# define FRAME_IN(frame)
# define FRAME_OUT(frame)
#endif
/*
* In some threading configurations, particular on Windows,
* we can't have executables reference our thread-local thread
@ -732,6 +757,7 @@ _finishKwarg:
frame->slots = (krk_currentThread.stackTop - argCount) - krk_currentThread.stack;
frame->outSlots = (krk_currentThread.stackTop - argCount - extra) - krk_currentThread.stack;
frame->globals = &closure->function->globalsContext->fields;
FRAME_IN(frame);
return 1;
_errorDuringPositionals:
@ -2031,6 +2057,7 @@ _finishReturn: (void)0;
krk_currentThread.stackTop[-2] = result;
break;
}
FRAME_OUT(frame);
krk_currentThread.frameCount--;
if (krk_currentThread.frameCount == 0) {
krk_pop();