kuroko/tools/callgrind.c

/**
 * @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 "../src/opcode_enum.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 [-f LOG_FILE] [-q] [-m] FILE [args...]\n", argv[0]);
	return 1;
}

static int help(char * argv[]) {
	usage(argv);
	fprintf(stderr,
		"Generate callgrind-format trace files.\n"
		"\n"
		"Options:\n"
		" -f LOG_FILE Output callgrind-format data to LOG_FILE.\n"
		" -q          Do not print execution summary.\n"
		" -m          Interpret first argument as a module name rather than a file.\n"
		"\n"
		" --help      Show this help text.\n"
		"\n");
	return 0;
}

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 */
static int    quiet = 0;
static int    moduleAsMain = 0;

/**
 * @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;
}

static void fprint_krk(FILE * f, const char * fmt, ...) {
	va_list args;
	va_start(args, fmt);
	struct StringBuilder sb = {0};
	krk_pushStringBuilderFormatV(&sb, fmt, args);
	fwrite(sb.bytes, sb.length, 1, f);
	krk_discardStringBuilder(&sb);
}

int main(int argc, char *argv[]) {
	char outfile[1024];
	snprintf(outfile,1024,"callgrind.out.%d",getpid());

	int opt;
	while ((opt = getopt(argc, argv, "+:f:qm-:")) != -1) {
		switch (opt) {
			case 'f':
				snprintf(outfile,1024,"%s", optarg);
				break;
			case 'q':
				quiet = 1;
				break;
			case 'm':
				moduleAsMain = 1;
				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")) {
					return help(argv);
				} 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);
	KrkValue argList = addArgs(argc,argv);

	krk_startModule("__callgrind__");

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

	if (moduleAsMain) {
		krk_importModule(AS_STRING(AS_LIST(argList)->values[0]), S("__main__"));
		if (krk_currentThread.flags & KRK_THREAD_HAS_EXCEPTION) krk_dumpTraceback();
		/* no need to reset here */
	} else {
		krk_startModule("__main__");
		krk_runfile(argv[optind],argv[optind]);
	}

	if (krk_currentThread.flags & KRK_THREAD_HAS_EXCEPTION) {
		krk_currentThread.flags &= ~(KRK_THREAD_HAS_EXCEPTION);
		if (!quiet) fprintf(stderr, "== Executed ended by exception ==\n");
	} else {
		if (!quiet) fprintf(stderr, "== Execution completed ==\n");
	}
	krk_callgrind_debuggerHook(NULL);

	if (!quiet) {
		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");
	fprint_krk(f,"cmd: %R\n", argList);
	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));
			fprint_krk(f,"0 %R\n", timeValue);
		}

		for (size_t k = 0; k < AS_DICT(ndict)->used; ++k) {
			if (IS_KWARGS(AS_DICT(ndict)->entries[k].key)) continue;
			fprint_krk(f,"%R %R 0\n", AS_DICT(ndict)->entries[k].key, AS_DICT(ndict)->entries[k].value);
		}

		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);
				fprint_krk(f,"calls=%R %R\n%R %R %R\n", totalCalls, targetLine, sourceLine, totalCost, totalTime);
			}
		}
	}

	fclose(f);

	krk_freeVM();
	return 0;
}