diff --git a/mps/code/clock.h b/mps/code/clock.h index 881d74e2715..920a69c9bee 100644 --- a/mps/code/clock.h +++ b/mps/code/clock.h @@ -120,7 +120,7 @@ __extension__ typedef unsigned long long EventClock; #define EVENT_CLOCK_PRINT(stream, clock) \ fprintf(stream, "%08lX%08lX", \ (unsigned long)((clock) >> 32), \ - (unsigned long)(clock)) + (unsigned long)((clock) & 0xffffffff)) #define EVENT_CLOCK_WRITE(stream, clock) \ WriteF(stream, "$W$W", (WriteFW)((clock) >> 32), (WriteFW)clock, NULL) diff --git a/mps/code/event.c b/mps/code/event.c index a3331d18c18..f88600df7e7 100644 --- a/mps/code/event.c +++ b/mps/code/event.c @@ -178,6 +178,8 @@ void EventInit(void) EventKindControl = (Word)mps_lib_telemetry_control(); EventInternSerial = (Serial)1; /* 0 is reserved */ (void)EventInternString(MPSVersion()); /* emit version */ + EVENT6(EventInit, EVENT_VERSION_MAJOR, EVENT_VERSION_MEDIAN, + EVENT_VERSION_MINOR, EventCodeMAX, EventNameMAX, MPS_WORD_WIDTH); } else { ++eventUserCount; } diff --git a/mps/code/eventcnv.c b/mps/code/eventcnv.c index 397b4350f47..d1c9de4d518 100644 --- a/mps/code/eventcnv.c +++ b/mps/code/eventcnv.c @@ -2,7 +2,7 @@ * Copyright (c) 2001 Ravenbrook Limited. See end of file for license. * * This is a command-line tool that converts a binary format telemetry output - * stream from the MPS into several textual formats. + * stream from the MPS into a textual format. * * The default MPS library will write a telemetry stream to a file called * "mpsio.log" when the environment variable MPS_TELEMETRY_CONTROL is set @@ -22,20 +22,16 @@ */ #include "config.h" - #include "eventdef.h" #include "eventcom.h" #include "eventpro.h" -#include "mpmtypes.h" #include "testlib.h" /* for ulongest_t and associated print formats */ #include /* for size_t */ #include /* for printf */ -#include /* for va_list */ #include /* for EXIT_FAILURE */ #include /* for assert */ #include /* for strcmp */ -#include /* for sqrt */ #include "mpstd.h" #ifdef MPS_BUILD_MV @@ -44,20 +40,12 @@ #pragma warning( disable : 4996 ) #endif - - -typedef unsigned int uint; -typedef unsigned long ulong; - +#define DEFAULT_TELEMETRY_FILENAME "mpsio.log" +#define TELEMETRY_FILENAME_ENVAR "MPS_TELEMETRY_FILENAME" static EventClock eventTime; /* current event time */ static char *prog; /* program name */ - -/* style: '\0' for human-readable, 'L' for Lisp, 'C' for CDF. */ -static char style = '\0'; - - /* everror -- error signalling */ static void everror(const char *format, ...) @@ -80,7 +68,7 @@ static void everror(const char *format, ...) static void usage(void) { fprintf(stderr, - "Usage: %s [-f logfile] [-S[LC]] [-h]\n" + "Usage: %s [-f logfile] [-h]\n" "See \"Telemetry\" in the reference manual for instructions.\n", prog); } @@ -99,7 +87,7 @@ static void usageError(void) static char *parseArgs(int argc, char *argv[]) { - char *name = "mpsio.log"; + char *name = NULL; int i = 1; if (argc >= 1) @@ -117,9 +105,6 @@ static char *parseArgs(int argc, char *argv[]) else name = argv[i]; break; - case 'S': /* style */ - style = argv[i][2]; /* '\0' for human-readable, 'L' for Lisp, */ - break; /* 'C' for CDF. */ case '?': case 'h': /* help */ usage(); exit(EXIT_SUCCESS); @@ -135,119 +120,39 @@ static char *parseArgs(int argc, char *argv[]) /* Printing routines */ +static void printHex(ulongest_t val) +{ + printf(" %"PRIXLONGEST, (ulongest_t)val); +} + +#define printParamP(p) printHex((ulongest_t)p) +#define printParamA(a) printHex((ulongest_t)a) +#define printParamU(u) printHex((ulongest_t)u) +#define printParamW(w) printHex((ulongest_t)w) +#define printParamB(b) printHex((ulongest_t)b) -/* printStr -- print an EventString */ +static void printParamD(double d) +{ + printf(" %.10G", d); +} -static void printStr(const char *str, Bool quotes) +static void printParamS(const char *str) { size_t i; - - if (quotes) putchar('"'); + putchar(' '); + putchar('"'); for (i = 0; str[i] != '\0'; ++i) { char c = str[i]; - if (quotes && (c == '"' || c == '\\')) putchar('\\'); + if (c == '"' || c == '\\') putchar('\\'); putchar(c); } - if (quotes) putchar('"'); + putchar('"'); } - -/* printAddr -- print an Addr or its label */ - -static void printAddr(EventProc proc, Addr addr) -{ - UNUSED(proc); - printf(style != 'C' ? - " %0"PRIwWORD PRIXLONGEST : - " %"PRIuLONGEST, - (ulongest_t)addr); -} - - -/* printParam* -- printing functions for event parameter types */ - -static void printParamA(EventProc proc, char *styleConv, Addr addr) -{ - if (style != 'L') { - if (style == 'C') putchar(','); - printAddr(proc, addr); - } else - printf(styleConv, (ulongest_t)addr); -} - -static void printParamP(EventProc proc, char *styleConv, void *p) -{ - UNUSED(proc); - printf(styleConv, (ulongest_t)p); -} - -static void printParamU(EventProc proc, char *styleConv, unsigned u) -{ - UNUSED(proc); - printf(styleConv, (ulongest_t)u); -} - -static void printParamW(EventProc proc, char *styleConv, Word w) -{ - UNUSED(proc); - printf(styleConv, (ulongest_t)w); -} - -static void printParamD(EventProc proc, char *styleConv, double d) -{ - UNUSED(proc); - UNUSED(styleConv); - switch (style) { - case '\0': - printf(" %#8.3g", d); break; - case 'C': - printf(", %.10G", d); break; - case 'L': - printf(" %#.10G", d); break; - } -} - -static void printParamS(EventProc proc, char *styleConv, const char *s) -{ - UNUSED(proc); - UNUSED(styleConv); - if (style == 'C') putchar(','); - putchar(' '); - printStr(s, (style == 'C' || style == 'L')); -} - -static void printParamB(EventProc proc, char *styleConv, Bool b) -{ - UNUSED(proc); - printf(styleConv, (ulongest_t)b); -} - - -/* readLog -- read and parse log - * - * This is the heart of eventcnv: It reads an event log using - * EventRead. It updates the counters. It looks up the format, - * parses the arguments, and prints a representation of the event. - * Each argument is printed using printArg (see RELATION, below), - * except for some event types that are handled specially. - */ +/* readLog -- read and parse log */ static void readLog(EventProc proc) { - char *styleConv = NULL; /* suppress uninit warning */ - - /* Init style. */ - switch (style) { - case '\0': - styleConv = " %8"PRIXLONGEST; break; - case 'C': - styleConv = ", %"PRIuLONGEST; break; - case 'L': - styleConv = " %"PRIXLONGEST; break; - default: - everror("Unknown style code '%c'", style); - } - while (TRUE) { /* loop for each event */ Event event; EventCode code; @@ -260,128 +165,25 @@ static void readLog(EventProc proc) eventTime = event->any.clock; code = event->any.code; - /* Output event. */ - { - if (style == 'L') putchar('('); + EVENT_CLOCK_PRINT(stdout, eventTime); + printf(" %X", (unsigned)code); - switch (style) { - case '\0': case 'L': - EVENT_CLOCK_PRINT(stdout, eventTime); - putchar(' '); - break; - case 'C': - EVENT_CLOCK_PRINT(stdout, eventTime); - fputs(", ", stdout); - break; - } - - switch (style) { - case '\0': case 'L': { - printf("%-19s ", EventCode2Name(code)); - } break; - case 'C': - printf("%u", (unsigned)code); - break; - } - - switch (code) { - - case EventLabelCode: - switch (style) { - case '\0': case 'C': - { - const char *sym = LabelText(proc, event->Label.f1); - printf(style == '\0' ? - " %08"PRIXLONGEST" " : - ", %"PRIuLONGEST", ", - (ulongest_t)event->Label.f0); - if (sym != NULL) { - printStr(sym, (style == 'C')); - } else { - printf(style == '\0' ? - "sym %05"PRIXLONGEST : - "sym %"PRIXLONGEST"\"", - (ulongest_t)event->Label.f1); - } - } - break; - case 'L': - printf(" %"PRIXLONGEST" %"PRIXLONGEST, - (ulongest_t)event->Label.f0, - (ulongest_t)event->Label.f1); - break; - } - break; - - case EventMeterValuesCode: - switch (style) { - case '\0': - if (event->MeterValues.f3 == 0) { - printf(" %08"PRIXLONGEST" 0 N/A N/A N/A N/A", - (ulongest_t)event->MeterValues.f0); - } else { - double mean = event->MeterValues.f1 / (double)event->MeterValues.f3; - /* .stddev: stddev = sqrt(meanSquared - mean^2), but see */ - /* . */ - double stddev = sqrt(fabs(event->MeterValues.f2 - - (mean * mean))); - printf(" %08"PRIXLONGEST" %8u %8u %8u %#8.3g %#8.3g", - (ulongest_t)event->MeterValues.f0, (uint)event->MeterValues.f3, - (uint)event->MeterValues.f4, (uint)event->MeterValues.f5, - mean, stddev); - } - printAddr(proc, (Addr)event->MeterValues.f0); - break; - - case 'C': - putchar(','); - printAddr(proc, (Addr)event->MeterValues.f0); - printf(", %.10G, %.10G, %u, %u, %u", - event->MeterValues.f1, event->MeterValues.f2, - (uint)event->MeterValues.f3, (uint)event->MeterValues.f4, - (uint)event->MeterValues.f5); - break; - - case 'L': - printf(" %"PRIXLONGEST" %#.10G %#.10G %X %X %X", - (ulongest_t)event->MeterValues.f0, - event->MeterValues.f1, event->MeterValues.f2, - (uint)event->MeterValues.f3, (uint)event->MeterValues.f4, - (uint)event->MeterValues.f5); - break; - } - break; - - case EventPoolInitCode: /* pool, arena, class */ - printf(styleConv, (ulongest_t)event->PoolInit.f0); - printf(styleConv, (ulongest_t)event->PoolInit.f1); - /* class is a Pointer, but we label them, so call printAddr */ - if (style != 'L') { - if (style == 'C') putchar(','); - printAddr(proc, (Addr)event->PoolInit.f2); - } else - printf(styleConv, (ulongest_t)event->PoolInit.f2); - break; - - default: + switch (code) { #define EVENT_PARAM_PRINT(name, index, sort, ident) \ - printParam##sort(proc, styleConv, event->name.f##index); + printParam##sort(event->name.f##index); #define EVENT_PRINT(X, name, code, always, kind) \ case code: \ EVENT_##name##_PARAMS(EVENT_PARAM_PRINT, name) \ break; - switch (code) { EVENT_LIST(EVENT_PRINT, X) } - } - - if (style == 'L') putchar(')'); - putchar('\n'); - fflush(stdout); + EVENT_LIST(EVENT_PRINT, X) } + + putchar('\n'); + fflush(stdout); EventDestroy(proc, event); } /* while(!feof(input)) */ } - /* logReader -- reader function for a file log */ static FILE *input; @@ -413,9 +215,14 @@ int main(int argc, char *argv[]) assert(CHECKCONV(ulongest_t, Addr)); assert(CHECKCONV(ulongest_t, void *)); assert(CHECKCONV(ulongest_t, EventCode)); - assert(CHECKCONV(Addr, void *)); /* for labelled pointers */ filename = parseArgs(argc, argv); + if (!filename) { + filename = getenv(TELEMETRY_FILENAME_ENVAR + ); + if(!filename) + filename = DEFAULT_TELEMETRY_FILENAME; + } if (strcmp(filename, "-") == 0) input = stdin; diff --git a/mps/code/eventdef.h b/mps/code/eventdef.h index df80bb6d1c2..456d230d8f8 100644 --- a/mps/code/eventdef.h +++ b/mps/code/eventdef.h @@ -38,7 +38,7 @@ #define EVENT_VERSION_MAJOR ((unsigned)1) #define EVENT_VERSION_MEDIAN ((unsigned)0) -#define EVENT_VERSION_MINOR ((unsigned)0) +#define EVENT_VERSION_MINOR ((unsigned)1) /* EVENT_LIST -- list of event types and general properties @@ -68,7 +68,7 @@ */ #define EventNameMAX ((size_t)19) -#define EventCodeMAX ((EventCode)0x0073) +#define EventCodeMAX ((EventCode)0x0074) #define EVENT_LIST(EVENT, X) \ /* 0123456789012345678 <- don't exceed without changing EventNameMAX */ \ @@ -179,7 +179,8 @@ EVENT(X, TraceFindGrey , 0x0070, TRUE, Trace) \ EVENT(X, TraceBandAdvance , 0x0071, TRUE, Trace) \ EVENT(X, AWLDeclineTotal , 0x0072, TRUE, Trace) \ - EVENT(X, AWLDeclineSeg , 0x0073, TRUE, Trace) + EVENT(X, AWLDeclineSeg , 0x0073, TRUE, Trace) \ + EVENT(X, EventInit , 0x0074, TRUE, Arena) /* Remember to update EventNameMAX and EventCodeMAX in eventcom.h! @@ -620,6 +621,14 @@ PARAM(X, 0, P, seg) /* segment declined single access */ \ PARAM(X, 1, W, singleAccesses) /* single accesses this cycle */ +#define EVENT_EventInit_PARAMS(PARAM, X) \ + PARAM(X, 0, U, major) /* EVENT_VERSION_MAJOR */ \ + PARAM(X, 1, U, median) /* EVENT_VERSION_MEDIAN */ \ + PARAM(X, 2, U, minor) /* EVENT_VERSION_MINOR */ \ + PARAM(X, 3, U, maxCode) /* EventCodeMAX */ \ + PARAM(X, 4, U, maxNameLen) /* EventNameMAX */ \ + PARAM(X, 5, U, wordWidth) /* MPS_WORD_WIDTH */ + #endif /* eventdef_h */ diff --git a/mps/code/eventsql.c b/mps/code/eventsql.c new file mode 100644 index 00000000000..b8ac5d6e4f5 --- /dev/null +++ b/mps/code/eventsql.c @@ -0,0 +1,950 @@ +/* eventsql.c: event log to SQLite importer. + * + * $Id$ + * + * Copyright (c) 2012 Ravenbrook Limited. See end of file for license. + * + * This is a command-line tool that imports events from a text-format + * MPS telemetry file into a SQLite database file. + * + * The default MPS library will write a binary-format telemetry file. + * The binary-format file can be converted into a text-format file + * using the eventcnv program with the -SC -v options. For + * binary-format compatibility, eventcnv has to be run on the same + * platform as the MPS. + * + * These ASCII text-format files have one line per event, and can be + * manipulated by various splendid systems in the usual Unix way. This + * eventsql program is one such. + * + * Note that eventsql can read streams that come from an MPS running + * on another platform. This is another reason why we use the + * intermediate text-format file, rather than reading the + * binary-format file directly: you can run the MPS and then eventcnv + * on the target platform, then optionally analyse the resulting text + * file on some other machine. + * + * Each event type gets its own table in the database. These tables + * are created from the definitions in eventdef.h if they don't + * already exist. Each event becomes a single row in the appropriate + * table, which has a column for each event parameter, a time column + * for the event time field, and a log_serial column to identify the + * log file. Because the database schema depends on the event + * definitions in eventdef.h, eventsql has to be compiled using the + * same event header files as those used to compile the MPS and + * eventcnv which generated and processed the telemetry output. + * + * The program also creates several other tables: three 'glue' tables + * containing event metadata - event_kind (one row per kind), + * event_type (one row per type), and event_param (one row per + * parameter), all derived from eventdef.h - and the event_log table + * which has one row per log file imported (the log_serial column in + * the event tables is a primary key to this event_log table). + * + * No tables are created if they already exist, unless the -r + * (rebuild) switch is given. + * + * Options: + * + * -v (verbose): Increase verbosity. eventsql logs to stderr. By + * default, it doesn't log much; it can be made more and more + * loquacious by adding more -v switches. Given one or more -v + * switches, it also writes 'ticks' (periods) to stdout, to show + * progress (one dot is 100k events). + * + * -t (test): Run unit tests on parts of eventsql. There aren't many + * of these. TODO: write more unit tests. + * + * -f (force): Import the events to SQL even if the SQL database + * already includes a record of importing a matching log file. + * + * -r (rebuild): Drop the glue tables from SQL, which will force them + * to be recreated. Important if you change event types or kinds in + * eventdef.h. + * + * -l : Import events from the named logfile. Defaults to + * stdin. If the specified file (matched by size and modtime) has + * previously been imported to the same database, it will not be + * imported again unless -f is specified. + * + * -d : Import events to the named database file. If not + * specified, eventsql will use the MPS_EVENT_DATABASE environment + * variable, and default to mpsevent.db. + * + * $Id$ + */ + +#include "misc.h" +#include "config.h" +#include "eventdef.h" +#include "eventcom.h" + +#include +#include +#include +#include +#include + +#define DATABASE_NAME_ENVAR "MPS_EVENT_DATABASE" +#define DEFAULT_DATABASE_NAME "mpsevent.db" + +typedef sqlite3_int64 int64; + +/* we output rows of dots. One dot per SMALL_TICK events, + * BIG_TICK dots per row. */ + +#define SMALL_TICK 100000 +#define BIG_TICK 50 + +/* Utility code for logging to stderr with multiple log levels, + * and for reporting errors. + */ + +unsigned int verbosity = 0; + +#define LOG_ALWAYS 0 +#define LOG_OFTEN 1 +#define LOG_SOMETIMES 2 +#define LOG_SELDOM 3 +#define LOG_RARELY 4 + +static void vlog(unsigned int level, const char *format, va_list args) +{ + if (level <= verbosity) { + fflush(stderr); /* sync */ + fprintf(stderr, "log %d: ", level); + vfprintf(stderr, format, args); + fprintf(stderr, "\n"); + } +} + +static void log(unsigned int level, const char *format, ...) +{ + va_list args; + va_start(args, format); + vlog(level, format, args); + va_end(args); +} + +static void error(const char *format, ...) +{ + va_list args; + fprintf(stderr, "Fatal error: "); + va_start(args, format); + vlog(LOG_ALWAYS, format, args); + va_end(args); + exit(1); +} + +static void sqlite_error(int res, sqlite3 *db, const char *format, ...) +{ + va_list args; + log(LOG_ALWAYS, "Fatal SQL error %d", res); + va_start(args, format); + vlog(LOG_ALWAYS, format, args); + va_end(args); + log(LOG_ALWAYS, "SQLite message: %s\n", sqlite3_errmsg(db)); + exit(1); +} + +static char *prog; /* program name */ +static int rebuild = FALSE; +static int runTests = FALSE; +static int force = FALSE; +static char *databaseName = NULL; +static char *logFileName = NULL; + +static void usage(void) +{ + fprintf(stderr, + "Usage: %s [-rtf] [-l ] [-d ] [-v -v -v ...]\n", + prog); +} + +static void usageError(void) +{ + usage(); + error("Bad usage"); +} + +/* parseArgs -- parse command line arguments */ + +static void parseArgs(int argc, char *argv[]) +{ + int i = 1; + + if (argc >= 1) + prog = argv[0]; + else + prog = "unknown"; + + while (i < argc) { /* consider argument i */ + if (argv[i][0] == '-') { /* it's an option argument */ + switch (argv[i][1]) { + case 'v': /* verbosity */ + ++ verbosity; + break; + case 'r': /* rebuild */ + rebuild = TRUE; + break; + case 'f': /* force */ + force = TRUE; + break; + case 't': /* run tests */ + runTests = TRUE; + break; + case 'l': /* log file name */ + ++ i; + if (i == argc) + usageError(); + else + logFileName = argv[i]; + break; + case 'd': /* database file name */ + ++ i; + if (i == argc) + usageError(); + else + databaseName = argv[i]; + break; + case '?': case 'h': /* help */ + usage(); + break; + default: + usageError(); + } + } /* if option */ + ++ i; + } +} + +/* openDatabase(p) opens the database file and returns a SQLite 3 + * database connection object. */ + +static sqlite3 *openDatabase(void) +{ + sqlite3 *db; + int res; + + if (!databaseName) { + databaseName = getenv(DATABASE_NAME_ENVAR); + if(!databaseName) + databaseName = DEFAULT_DATABASE_NAME; + } + res = sqlite3_open_v2(databaseName, + &db, + SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE, + NULL); /* use default sqlite_vfs object */ + + if (res != SQLITE_OK) + sqlite_error(res, db, "Opening %s failed", databaseName); + + log(LOG_OFTEN, "Writing to %s.",databaseName); + + return db; +} + +/* closeDatabase(db) closes the database opened by openDatabase(). */ + +static void closeDatabase(sqlite3 *db) +{ + int res = sqlite3_close(db); + if (res != SQLITE_OK) + sqlite_error(res, db, "Closing database failed"); + log(LOG_SOMETIMES, "Closed %s.", databaseName); +} + +/* Utility functions for SQLite statements. */ + +static sqlite3_stmt *prepareStatement(sqlite3 *db, + const char *sql) +{ + int res; + sqlite3_stmt *statement; + log(LOG_SELDOM, "Preparing statement %s", sql); + res = sqlite3_prepare_v2(db, sql, + -1, /* prepare whole string as statement */ + &statement, + NULL); + if (res != SQLITE_OK) + sqlite_error(res, db, "statement preparation failed: %s", sql); + return statement; +} + +static void finalizeStatement(sqlite3 *db, + sqlite3_stmt *statement) +{ + int res; + res = sqlite3_finalize(statement); + if (res != SQLITE_OK) + sqlite_error(res, db, "statement finalize failed"); +} + +static void runStatement(sqlite3 *db, + const char *sql, + const char *description) +{ + int res; + log(LOG_SELDOM, "%s: %s", description, sql); + res = sqlite3_exec(db, + sql, + NULL, /* No callback */ + NULL, /* No callback closure */ + NULL); /* error messages handled by sqlite_error */ + if (res != SQLITE_OK) + sqlite_error(res, db, "%s failed - statement %s", description, sql); +} + +/* Test for the existence of a table using sqlite_master table. + */ + +static int tableExists(sqlite3* db, const char *tableName) +{ + int res; + int exists; + sqlite3_stmt *statement; + + statement = prepareStatement(db, + "SELECT 1 FROM sqlite_master WHERE type='table' AND name=?"); + res = sqlite3_bind_text(statement, 1, tableName, -1, SQLITE_STATIC); + if (res != SQLITE_OK) + sqlite_error(res, db, "table existence bind of name failed."); + res = sqlite3_step(statement); + switch(res) { + case SQLITE_DONE: + exists = 0; + break; + case SQLITE_ROW: + exists = 1; + break; + default: + sqlite_error(res, db, "select from sqlite_master failed."); + } + finalizeStatement(db, statement); + return exists; +} + +/* Unit test for tableExists() */ + +static struct { + const char* name; + int exists; +} tableTests[] = { + {"event_kind", TRUE}, + {"spong", FALSE}, + {"EVENT_SegSplit", TRUE} +}; + +static void testTableExists(sqlite3 *db) +{ + size_t i; + int defects = 0; + int tests = 0; + for (i=0; i < (sizeof(tableTests)/sizeof(tableTests[0])); ++i) { + const char *name = tableTests[i].name; + int exists = tableExists(db, name); + if (exists) + log(LOG_OFTEN, "Table exists: %s", name); + else + log(LOG_OFTEN, "Table does not exist: %s", name); + if (exists != tableTests[i].exists) { + log(LOG_ALWAYS, "tableExists test failed on table %s", name); + ++ defects; + } + ++ tests; + } + log(LOG_ALWAYS, "%d tests, %d defects found.", tests, defects); +} + +/* Every time we put events from a log file into a database file, we + * add the log file to the event_log table, and get a serial number + * from SQL which is then attached to all event rows from that log. + * We use this to record overall SQL activity, to deter mistaken + * attempts to add the same log file twice, and to allow events from + * several different log files to share the same SQL file. + * + * When reading events from stdin, we can't so easily avoid the + * duplication (unless we, e.g., take a hash of the event set); we + * assume that the user is smart enough not to do that. + */ + +static int64 logSerial = 0; + +static void registerLogFile(sqlite3 *db, + const char *filename) +{ + sqlite3_stmt *statement; + int res; + const unsigned char *name; + int64 completed; + int64 file_size; + int64 file_modtime; + + if (filename) { + struct stat st; + res = stat(filename, &st); + if (res != 0) + error("Couldn't stat() %s", filename); + file_size = st.st_size; + file_modtime = st.st_mtime; + + statement = prepareStatement(db, + "SELECT name, serial, completed FROM event_log" + " WHERE size = ? AND modtime = ?"); + res = sqlite3_bind_int64(statement, 1, file_size); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log bind of size failed."); + res = sqlite3_bind_int64(statement, 2, file_modtime); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log bind of modtime failed."); + res = sqlite3_step(statement); + switch(res) { + case SQLITE_DONE: + log(LOG_SOMETIMES, "No log file matching '%s' found in database.", filename); + break; + case SQLITE_ROW: + name = sqlite3_column_text(statement, 0); + logSerial = sqlite3_column_int64(statement, 1); + completed = sqlite3_column_int64(statement, 2); + log(force ? LOG_OFTEN : LOG_ALWAYS, "Log file matching '%s' already in event_log, named \"%s\" (serial %lu, completed %lu).", + filename, name, logSerial, completed); + if (force) { + log(LOG_OFTEN, "Continuing anyway because -f specified."); + } else { + log(LOG_ALWAYS, "Exiting. Specify -f to force events into SQL anyway."); + exit(0); + } + break; + default: + sqlite_error(res, db, "select from event_log failed."); + } + finalizeStatement(db, statement); + } else { /* stdin */ + filename = ""; + file_size = 0; + file_modtime = 0; + } + statement = prepareStatement(db, + "INSERT into event_log (name, size, modtime, completed)" + " VALUES (?, ?, ?, 0)"); + res = sqlite3_bind_text(statement, 1, filename, -1, SQLITE_STATIC); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log insert bind of name failed."); + res = sqlite3_bind_int64(statement, 2, file_size); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log insert bind of size failed."); + res = sqlite3_bind_int64(statement, 3, file_modtime); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log insert bind of modtime failed."); + res = sqlite3_step(statement); + if (res != SQLITE_DONE) + sqlite_error(res, db, "insert into event_log failed."); + logSerial = sqlite3_last_insert_rowid(db); + log(LOG_SOMETIMES, "Log file %s added to event_log with serial %lu", + filename, logSerial); + finalizeStatement(db, statement); +} + +static void logFileCompleted(sqlite3 *db, + int64 completed) +{ + sqlite3_stmt *statement; + int res; + + statement = prepareStatement(db, + "UPDATE event_log SET completed=? WHERE serial=?"); + res = sqlite3_bind_int64(statement, 2, logSerial); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log update bind of serial failed."); + res = sqlite3_bind_int64(statement, 1, completed); + if (res != SQLITE_OK) + sqlite_error(res, db, "event_log update bind of completed failed."); + res = sqlite3_step(statement); + if (res != SQLITE_DONE) + sqlite_error(res, db, "insert into event_log failed."); + log(LOG_SOMETIMES, "Marked in event_log: %lu events", completed); + finalizeStatement(db, statement); +} + +/* Macro magic to make a CREATE TABLE statement for each event type. */ + +#define EVENT_PARAM_SQL_TYPE_A "INTEGER" +#define EVENT_PARAM_SQL_TYPE_P "INTEGER" +#define EVENT_PARAM_SQL_TYPE_U "INTEGER" +#define EVENT_PARAM_SQL_TYPE_W "INTEGER" +#define EVENT_PARAM_SQL_TYPE_D "REAL " +#define EVENT_PARAM_SQL_TYPE_S "TEXT " +#define EVENT_PARAM_SQL_TYPE_B "INTEGER" + +#define EVENT_PARAM_SQL_COLUMN(X, index, sort, ident) \ + "\"" #ident "\" " EVENT_PARAM_SQL_TYPE_##sort ", " + +#define EVENT_TABLE_CREATE(X, name, code, always, kind) \ + "CREATE TABLE IF NOT EXISTS EVENT_" #name " ( " \ + EVENT_##name##_PARAMS(EVENT_PARAM_SQL_COLUMN, X) \ + "time INTEGER, " \ + "log_serial INTEGER)", + +/* An array of table-creation statement strings. */ + +const char *createStatements[] = { + "CREATE TABLE IF NOT EXISTS event_kind (name TEXT," + " description TEXT," + " enum INTEGER PRIMARY KEY)", + + "CREATE TABLE IF NOT EXISTS event_type (name TEXT," + " code INTEGER PRIMARY KEY," + " always INTEGER," + " kind INTEGER," + " FOREIGN KEY (kind) REFERENCES event_kind(enum));", + + "CREATE TABLE IF NOT EXISTS event_param (type INTEGER," + " param_index INTEGER," + " sort TEXT," + " ident TEXT," + " FOREIGN KEY (type) REFERENCES event_type(code));", + + "CREATE TABLE IF NOT EXISTS event_log (name TEXT," + " size INTEGER," + " modtime INTEGER," + " completed INTEGER," + " serial INTEGER PRIMARY KEY AUTOINCREMENT)", + +EVENT_LIST(EVENT_TABLE_CREATE, X) +}; + +/* makeTables makes all the tables. */ + +static void makeTables(sqlite3 *db) +{ + size_t i; + log(LOG_SOMETIMES, "Creating tables."); + + for (i=0; i < (sizeof(createStatements)/sizeof(createStatements[0])); ++i) { + runStatement(db, createStatements[i], "Table creation"); + } +} + +const char *glueTables[] = { + "event_kind", + "event_type", + "event_param", +}; + +static void dropGlueTables(sqlite3 *db) +{ + size_t i; + int res; + char sql[1024]; + + log(LOG_ALWAYS, "Dropping glue tables so they are rebuilt."); + + for (i=0; i < (sizeof(glueTables)/sizeof(glueTables[0])); ++i) { + log(LOG_SOMETIMES, "Dropping table %s", glueTables[i]); + sprintf(sql, "DROP TABLE %s", glueTables[i]); + res = sqlite3_exec(db, + sql, + NULL, /* No callback */ + NULL, /* No callback closure */ + NULL); /* error messages handled by sqlite_error */ + /* Don't check for errors. */ + } +} + +/* Populate the metadata "glue" tables event_kind, event_type, and + * event_param. */ + +#define EVENT_KIND_DO_INSERT(X, name, description) \ + res = sqlite3_bind_text(statement, 1, #name, -1, SQLITE_STATIC); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_kind bind of name \"" #name "\" failed."); \ + res = sqlite3_bind_text(statement, 2, description, -1, SQLITE_STATIC); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_kind bind of description \"" description "\" failed."); \ + res = sqlite3_bind_int(statement, 3, i); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_kind bind of enum %d failed.", i); \ + ++i; \ + res = sqlite3_step(statement); \ + if (res != SQLITE_DONE) \ + sqlite_error(res, db, "event_kind insert of name \"" #name "\" failed."); \ + if (sqlite3_changes(db) != 0) \ + log(LOG_SOMETIMES, "Insert of event_kind row for \"" #name "\" affected %d rows.", sqlite3_changes(db)); \ + res = sqlite3_reset(statement); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "Couldn't reset event_kind insert statement."); + +#define EVENT_TYPE_DO_INSERT(X, name, code, always, kind) \ + res = sqlite3_bind_text(statement, 1, #name, -1, SQLITE_STATIC); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_type bind of name \"" #name "\" failed."); \ + res = sqlite3_bind_int(statement, 2, code); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_type bind of code %d failed.", code); \ + res = sqlite3_bind_int(statement, 3, always); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_type bind of always for name \"" #name "\" failed."); \ + res = sqlite3_bind_int(statement, 4, EventKind##kind); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_type bind of kind for name \"" #name "\" failed."); \ + res = sqlite3_step(statement); \ + if (res != SQLITE_DONE) \ + sqlite_error(res, db, "event_type insert of name \"" #name "\" failed."); \ + if (sqlite3_changes(db) != 0) \ + log(LOG_SOMETIMES, "Insert of event_type row for \"" #name "\" affected %d rows.", sqlite3_changes(db)); \ + res = sqlite3_reset(statement); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "Couldn't reset event_type insert statement."); + +#define EVENT_PARAM_DO_INSERT(code, index, sort, ident) \ + res = sqlite3_bind_int(statement, 1, code); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_param bind of code %d failed.", code); \ + res = sqlite3_bind_int(statement, 2, index); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_param bind of index %d failed.", index); \ + res = sqlite3_bind_text(statement, 3, #sort, -1, SQLITE_STATIC); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_type bind of sort \"" #sort "\" failed."); \ + res = sqlite3_bind_text(statement, 4, #ident, -1, SQLITE_STATIC); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "event_type bind of ident \"" #ident "\" failed."); \ + res = sqlite3_step(statement); \ + if (res != SQLITE_DONE) \ + sqlite_error(res, db, "event_param insert of ident \"" #ident "\" for code %d failed.", code); \ + if (sqlite3_changes(db) != 0) \ + log(LOG_SOMETIMES, "Insert of event_param row for code %d, ident \"" #ident "\" affected %d rows.", code, sqlite3_changes(db)); \ + res = sqlite3_reset(statement); \ + if (res != SQLITE_OK) \ + sqlite_error(res, db, "Couldn't reset event_param insert statement."); + +#define EVENT_TYPE_INSERT_PARAMS(X, name, code, always, kind) \ + EVENT_##name##_PARAMS(EVENT_PARAM_DO_INSERT, code) + +static void fillGlueTables(sqlite3 *db) +{ + int i; + sqlite3_stmt *statement; + int res; + + statement = prepareStatement(db, + "INSERT OR IGNORE INTO event_kind (name, description, enum)" + "VALUES (?, ?, ?)"); + + i = 0; + EventKindENUM(EVENT_KIND_DO_INSERT, X); + + finalizeStatement(db, statement); + + statement = prepareStatement(db, + "INSERT OR IGNORE INTO event_type (name, code, always, kind)" + "VALUES (?, ?, ?, ?)"); + EVENT_LIST(EVENT_TYPE_DO_INSERT, X); + + finalizeStatement(db, statement); + + statement = prepareStatement(db, + "INSERT OR IGNORE INTO event_param (type, param_index, sort, ident)" + "VALUES (?, ?, ?, ?)"); + EVENT_LIST(EVENT_TYPE_INSERT_PARAMS, X); + + finalizeStatement(db, statement); +} + +/* Populate the actual event tables. */ + +#define EVENT_TYPE_DECLARE_STATEMENT(X, name, code, always, kind) \ + sqlite3_stmt *stmt_##name; + +#define EVENT_PARAM_PREPARE_IDENT(X, index, sort, ident) "\"" #ident "\", " + +#define EVENT_PARAM_PREPARE_PLACE(X, index, sort, ident) "?, " + +#define EVENT_TYPE_PREPARE_STATEMENT(X, name, code, always, kind) \ + stmt_##name = \ + prepareStatement(db, \ + "INSERT INTO EVENT_" #name " (" \ + EVENT_##name##_PARAMS(EVENT_PARAM_PREPARE_IDENT, X) \ + "log_serial, time) VALUES (" \ + EVENT_##name##_PARAMS(EVENT_PARAM_PREPARE_PLACE,X) \ + "?, ?)"); + +#define EVENT_TYPE_FINALIZE_STATEMENT(X, name, code, always, kind) \ + finalizeStatement(db, stmt_##name); + +#define EVENT_PARAM_BIND_A bind_int +#define EVENT_PARAM_BIND_P bind_int +#define EVENT_PARAM_BIND_U bind_int +#define EVENT_PARAM_BIND_W bind_int +#define EVENT_PARAM_BIND_D bind_real +#define EVENT_PARAM_BIND_S bind_text +#define EVENT_PARAM_BIND_B bind_int + +#define EVENT_PARAM_BIND(X, index, sort, ident) \ + p = EVENT_PARAM_BIND_##sort (db, statement, eventCount, index+1, p); \ + last_index = index+1; + +#define EVENT_TYPE_WRITE_SQL(X, name, code, always, kind) \ + case code: \ + statement = stmt_##name; \ + /* bind all the parameters of this particular event with macro magic. */ \ + EVENT_##name##_PARAMS(EVENT_PARAM_BIND, X) \ + break; + +static char *bind_int(sqlite3 *db, sqlite3_stmt *stmt, int64 count, int index, char *p) +{ + char *q; + long long val; + int res; + + while(*p == ' ') + ++p; + + val = strtoll(p, &q, 16); + if (q == p) + error("event %llu field %d not an integer: %s", + count, index, p); + + res = sqlite3_bind_int64(stmt, index, val); + if (res != SQLITE_OK) + sqlite_error(res, db, "event %llu field %d bind failed", count, index); + return q; +} + +static char *bind_real(sqlite3 *db, sqlite3_stmt *stmt, int64 count, int index, char *p) +{ + char *q; + double val; + int res; + + while(*p == ' ') + ++p; + + val = strtod(p, &q); + if (q == p) + error("event %llu field %d not a floating-point value: %s", + count, index, p); + + res = sqlite3_bind_double(stmt, index, val); + if (res != SQLITE_OK) + sqlite_error(res, db, "event %llu field %d bind failed", count, index); + return q; +} + +static char *bind_text(sqlite3 *db, sqlite3_stmt *stmt, int64 count, int index, char *p) +{ + char *q; + int res; + + while(*p == ' ') + ++p; + + q = p; + while((*q != '\n') && (*q != '\0')) { + ++ q; + } + if ((q == p) || (q[-1] != '"')) + error("event %llu string field %d has no closing quote mark.", + count, index); + + res = sqlite3_bind_text(stmt, index, p, (int)(q-p-1), SQLITE_STATIC); + if (res != SQLITE_OK) + sqlite_error(res, db, "event %llu field %d bind failed", count, index); + return q; +} + +/* readLog -- read and parse log. Returns the number of events written. + */ + +static int64 readLog(FILE *input, + sqlite3 *db) +{ + int64 eventCount = 0; + + /* declare statements for every event type */ + EVENT_LIST(EVENT_TYPE_DECLARE_STATEMENT, X); + + /* prepare statements for every event type */ + EVENT_LIST(EVENT_TYPE_PREPARE_STATEMENT, X); + + runStatement(db, "BEGIN", "Transaction start"); + + while (TRUE) { /* loop for each event */ + char line[1024]; + char *p; + char *q; + int last_index=0; + sqlite3_stmt *statement; + int res; + int64 clock; + long code; + + p = fgets(line, 1024, input); + if (!p) { + if (feof(input)) + break; + else + error("Couldn't read line after event %llu", eventCount); + } + + eventCount++; + + clock = strtoll(p, &q, 16); + if (q == p) + error("event %llu clock field not a hex integer: %s", + eventCount, p); + + if (*q != ' ') + error("event %llu code field not preceded by ' ': %s", + eventCount, q); + while(*q == ' ') + ++q; + + p = q; + code = strtol(p, &q, 16); + if (q == p) + error("event %llu code field %d not an integer: %s", + eventCount, index, p); + p = q; + /* Write event to SQLite. */ + switch (code) { + /* this macro sets statement and last_index */ + EVENT_LIST(EVENT_TYPE_WRITE_SQL, X); + default: + error("Event %llu has Unknown event code %d", eventCount, code); + } + /* bind the fields we store for every event */ \ + res = sqlite3_bind_int64(statement, last_index+1, logSerial); + if (res != SQLITE_OK) + sqlite_error(res, db, "Event %llu bind of log_serial failed.", eventCount); + res = sqlite3_bind_int64(statement, last_index+2, clock); + if (res != SQLITE_OK) + sqlite_error(res, db, "Event %llu bind of clock failed.", eventCount); + res = sqlite3_step(statement); + if (res != SQLITE_DONE) + sqlite_error(res, db, "insert of event %llu failed.", eventCount); + res = sqlite3_reset(statement); + if (res != SQLITE_OK) + sqlite_error(res, db, "Couldn't reset insert statement of event %llu", eventCount); + + if (verbosity > LOG_ALWAYS) { + if ((eventCount % SMALL_TICK) == 0) { + printf("."); + fflush(stdout); + if (((eventCount / SMALL_TICK) % BIG_TICK) == 0) { + printf("\n"); + fflush(stdout); + log(LOG_SOMETIMES, "%lu events.", (unsigned long)eventCount); + } + } + } + } + if (verbosity > LOG_ALWAYS) { + printf("\n"); + fflush(stdout); + } + runStatement(db, "COMMIT", "Transaction finish"); + logFileCompleted(db, eventCount); + + /* finalize all the statements */ + EVENT_LIST(EVENT_TYPE_FINALIZE_STATEMENT, X); + + return eventCount; +} + +static FILE *openLog(sqlite3 *db) +{ + FILE *input; + + registerLogFile(db, logFileName); + if (!logFileName) { + input = stdin; + logFileName = ""; + } else { + input = fopen(logFileName, "r"); + if (input == NULL) + error("unable to open %s", logFileName); + } + + log(LOG_OFTEN, "Reading %s.", logFileName ? logFileName : "standard input"); + + return input; +} + +static int64 writeEventsToSQL(sqlite3 *db) +{ + FILE *input; + int64 count; + input = openLog(db); + count = readLog(input, db); + (void)fclose(input); + return count; +} + + +int main(int argc, char *argv[]) +{ + sqlite3 *db; + int64 count; + + parseArgs(argc, argv); + + db = openDatabase(); + if (rebuild) { + dropGlueTables(db); + } + makeTables(db); + fillGlueTables(db); + count = writeEventsToSQL(db); + log(LOG_ALWAYS, "Imported %llu events from %s to %s, serial %lu.", + count, logFileName, databaseName, logSerial); + + if (runTests) { + /* TODO: more unit tests in here */ + testTableExists(db); + } + + closeDatabase(db); + return 0; +} + +/* COPYRIGHT AND LICENSE + * + * Copyright (C) 2012 Ravenbrook Limited . + * All rights reserved. This is an open source license. Contact + * Ravenbrook for commercial licensing options. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are + * met: + * + * 1. Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * + * 2. Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in the + * documentation and/or other materials provided with the distribution. + * + * 3. Redistributions in any form must be accompanied by information on how + * to obtain complete source code for this software and any accompanying + * software that uses this software. The source code must either be + * included in the distribution or be available for no more than the cost + * of distribution plus a nominal fee, and must be freely redistributable + * under reasonable conditions. For an executable file, complete source + * code means the source code for all modules it contains. It does not + * include source code for modules or files that typically accompany the + * major components of the operating system on which the executable file + * runs. + * + * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS + * IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED + * TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR + * PURPOSE, OR NON-INFRINGEMENT, ARE DISCLAIMED. IN NO EVENT SHALL THE + * COPYRIGHT HOLDERS AND CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, + * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT + * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF + * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON + * ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT + * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF + * THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + */ diff --git a/mps/code/mps.xcodeproj/project.pbxproj b/mps/code/mps.xcodeproj/project.pbxproj index 207e50660e4..0647bc91de2 100644 --- a/mps/code/mps.xcodeproj/project.pbxproj +++ b/mps/code/mps.xcodeproj/project.pbxproj @@ -13,6 +13,7 @@ buildPhases = ( ); dependencies = ( + 2D07B9791636FCBD00DB751B /* PBXTargetDependency */, 3104AFF6156D37BC000A585A /* PBXTargetDependency */, 3114A6D5156E9839001E0AA3 /* PBXTargetDependency */, 3114A6B9156E9763001E0AA3 /* PBXTargetDependency */, @@ -51,6 +52,8 @@ /* End PBXAggregateTarget section */ /* Begin PBXBuildFile section */ + 2D07B97A1636FCCE00DB751B /* eventsql.c in Sources */ = {isa = PBXBuildFile; fileRef = 2D07B96C1636FC7200DB751B /* eventsql.c */; }; + 2D07B97C163705E400DB751B /* libsqlite3.dylib in Frameworks */ = {isa = PBXBuildFile; fileRef = 2D07B97B163705E400DB751B /* libsqlite3.dylib */; }; 3104AFBF156D3591000A585A /* apss.c in Sources */ = {isa = PBXBuildFile; fileRef = 3104AFBE156D3591000A585A /* apss.c */; }; 3104AFC2156D35B2000A585A /* libmps.a in Frameworks */ = {isa = PBXBuildFile; fileRef = 31EEABFB156AAF9D00714D05 /* libmps.a */; }; 3104AFC3156D35C3000A585A /* testlib.c in Sources */ = {isa = PBXBuildFile; fileRef = 31EEAC9E156AB73400714D05 /* testlib.c */; }; @@ -196,6 +199,13 @@ /* End PBXBuildFile section */ /* Begin PBXContainerItemProxy section */ + 2D07B9781636FCBD00DB751B /* PBXContainerItemProxy */ = { + isa = PBXContainerItemProxy; + containerPortal = 31EEABDA156AAE9E00714D05 /* Project object */; + proxyType = 1; + remoteGlobalIDString = 2D07B9701636FC9900DB751B; + remoteInfo = eventsql; + }; 3104AFC0156D35AE000A585A /* PBXContainerItemProxy */ = { isa = PBXContainerItemProxy; containerPortal = 31EEABDA156AAE9E00714D05 /* Project object */; @@ -626,6 +636,15 @@ /* End PBXContainerItemProxy section */ /* Begin PBXCopyFilesBuildPhase section */ + 2D07B96F1636FC9900DB751B /* CopyFiles */ = { + isa = PBXCopyFilesBuildPhase; + buildActionMask = 2147483647; + dstPath = /usr/share/man/man1/; + dstSubfolderSpec = 0; + files = ( + ); + runOnlyForDeploymentPostprocessing = 1; + }; 3104AFB1156D357B000A585A /* CopyFiles */ = { isa = PBXCopyFilesBuildPhase; buildActionMask = 2147483647; @@ -899,6 +918,9 @@ /* End PBXCopyFilesBuildPhase section */ /* Begin PBXFileReference section */ + 2D07B96C1636FC7200DB751B /* eventsql.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = eventsql.c; sourceTree = ""; }; + 2D07B9711636FC9900DB751B /* eventsql */ = {isa = PBXFileReference; explicitFileType = "compiled.mach-o.executable"; includeInIndex = 0; path = eventsql; sourceTree = BUILT_PRODUCTS_DIR; }; + 2D07B97B163705E400DB751B /* libsqlite3.dylib */ = {isa = PBXFileReference; lastKnownFileType = "compiled.mach-o.dylib"; name = libsqlite3.dylib; path = usr/lib/libsqlite3.dylib; sourceTree = SDKROOT; }; 3104AFA5156D27E7000A585A /* ssixi6.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = ssixi6.c; sourceTree = ""; }; 3104AFB3156D357B000A585A /* apss */ = {isa = PBXFileReference; explicitFileType = "compiled.mach-o.executable"; includeInIndex = 0; path = apss; sourceTree = BUILT_PRODUCTS_DIR; }; 3104AFBE156D3591000A585A /* apss.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = apss.c; sourceTree = ""; }; @@ -1026,6 +1048,14 @@ /* End PBXFileReference section */ /* Begin PBXFrameworksBuildPhase section */ + 2D07B96E1636FC9900DB751B /* Frameworks */ = { + isa = PBXFrameworksBuildPhase; + buildActionMask = 2147483647; + files = ( + 2D07B97C163705E400DB751B /* libsqlite3.dylib in Frameworks */, + ); + runOnlyForDeploymentPostprocessing = 0; + }; 3104AFB0156D357B000A585A /* Frameworks */ = { isa = PBXFrameworksBuildPhase; buildActionMask = 2147483647; @@ -1276,6 +1306,21 @@ /* End PBXFrameworksBuildPhase section */ /* Begin PBXGroup section */ + 2D07B96A1636FC4C00DB751B /* eventsql */ = { + isa = PBXGroup; + children = ( + 2D07B96C1636FC7200DB751B /* eventsql.c */, + ); + name = eventsql; + sourceTree = ""; + }; + 2D07B9731636FC9900DB751B /* eventsql */ = { + isa = PBXGroup; + children = ( + ); + path = eventsql; + sourceTree = ""; + }; 3114A647156E956C001E0AA3 /* Mysterious */ = { isa = PBXGroup; children = ( @@ -1288,6 +1333,7 @@ 3114A6D6156E9846001E0AA3 /* Tools */ = { isa = PBXGroup; children = ( + 2D07B96A1636FC4C00DB751B /* eventsql */, 3114A6D8156E9942001E0AA3 /* eventcnv */, ); name = Tools; @@ -1374,10 +1420,12 @@ 31EEABD8156AAE9E00714D05 = { isa = PBXGroup; children = ( + 2D07B97B163705E400DB751B /* libsqlite3.dylib */, 3114A6D6156E9846001E0AA3 /* Tools */, 3114A647156E956C001E0AA3 /* Mysterious */, 31A47BA8156C1E930039B1C2 /* MPS */, 3124CAB3156BE1B700753214 /* Tests */, + 2D07B9731636FC9900DB751B /* eventsql */, 31EEABEF156AAF5C00714D05 /* Products */, ); sourceTree = ""; @@ -1416,6 +1464,7 @@ 3114A695156E971B001E0AA3 /* messtest */, 3114A6AC156E9759001E0AA3 /* walkt0 */, 3114A6C6156E9815001E0AA3 /* eventcnv */, + 2D07B9711636FC9900DB751B /* eventsql */, ); name = Products; sourceTree = ""; @@ -1515,6 +1564,23 @@ /* End PBXHeadersBuildPhase section */ /* Begin PBXNativeTarget section */ + 2D07B9701636FC9900DB751B /* eventsql */ = { + isa = PBXNativeTarget; + buildConfigurationList = 2D07B9741636FC9900DB751B /* Build configuration list for PBXNativeTarget "eventsql" */; + buildPhases = ( + 2D07B96D1636FC9900DB751B /* Sources */, + 2D07B96E1636FC9900DB751B /* Frameworks */, + 2D07B96F1636FC9900DB751B /* CopyFiles */, + ); + buildRules = ( + ); + dependencies = ( + ); + name = eventsql; + productName = eventsql; + productReference = 2D07B9711636FC9900DB751B /* eventsql */; + productType = "com.apple.product-type.tool"; + }; 3104AFB2156D357B000A585A /* apss */ = { isa = PBXNativeTarget; buildConfigurationList = 3104AFBC156D357B000A585A /* Build configuration list for PBXNativeTarget "apss" */; @@ -2124,11 +2190,20 @@ 3114A694156E971B001E0AA3 /* messtest */, 3114A6AB156E9759001E0AA3 /* walkt0 */, 3114A6C5156E9815001E0AA3 /* eventcnv */, + 2D07B9701636FC9900DB751B /* eventsql */, ); }; /* End PBXProject section */ /* Begin PBXSourcesBuildPhase section */ + 2D07B96D1636FC9900DB751B /* Sources */ = { + isa = PBXSourcesBuildPhase; + buildActionMask = 2147483647; + files = ( + 2D07B97A1636FCCE00DB751B /* eventsql.c in Sources */, + ); + runOnlyForDeploymentPostprocessing = 0; + }; 3104AFAF156D357B000A585A /* Sources */ = { isa = PBXSourcesBuildPhase; buildActionMask = 2147483647; @@ -2461,6 +2536,11 @@ /* End PBXSourcesBuildPhase section */ /* Begin PBXTargetDependency section */ + 2D07B9791636FCBD00DB751B /* PBXTargetDependency */ = { + isa = PBXTargetDependency; + target = 2D07B9701636FC9900DB751B /* eventsql */; + targetProxy = 2D07B9781636FCBD00DB751B /* PBXContainerItemProxy */; + }; 3104AFC1156D35AE000A585A /* PBXTargetDependency */ = { isa = PBXTargetDependency; target = 31EEABFA156AAF9D00714D05 /* mps */; @@ -2769,6 +2849,30 @@ /* End PBXTargetDependency section */ /* Begin XCBuildConfiguration section */ + 2D07B9751636FC9900DB751B /* Debug */ = { + isa = XCBuildConfiguration; + buildSettings = { + GCC_C_LANGUAGE_STANDARD = c99; + PRODUCT_NAME = "$(TARGET_NAME)"; + }; + name = Debug; + }; + 2D07B9761636FC9900DB751B /* Release */ = { + isa = XCBuildConfiguration; + buildSettings = { + GCC_C_LANGUAGE_STANDARD = c99; + PRODUCT_NAME = "$(TARGET_NAME)"; + }; + name = Release; + }; + 2D07B9771636FC9900DB751B /* WE */ = { + isa = XCBuildConfiguration; + buildSettings = { + GCC_C_LANGUAGE_STANDARD = c99; + PRODUCT_NAME = "$(TARGET_NAME)"; + }; + name = WE; + }; 3104AFBA156D357B000A585A /* Debug */ = { isa = XCBuildConfiguration; buildSettings = { @@ -3616,6 +3720,15 @@ /* End XCBuildConfiguration section */ /* Begin XCConfigurationList section */ + 2D07B9741636FC9900DB751B /* Build configuration list for PBXNativeTarget "eventsql" */ = { + isa = XCConfigurationList; + buildConfigurations = ( + 2D07B9751636FC9900DB751B /* Debug */, + 2D07B9761636FC9900DB751B /* Release */, + 2D07B9771636FC9900DB751B /* WE */, + ); + defaultConfigurationIsVisible = 0; + }; 3104AFBC156D357B000A585A /* Build configuration list for PBXNativeTarget "apss" */ = { isa = XCConfigurationList; buildConfigurations = ( diff --git a/mps/code/mpsliban.c b/mps/code/mpsliban.c index 8abab586319..f966df6f4f2 100644 --- a/mps/code/mpsliban.c +++ b/mps/code/mpsliban.c @@ -36,6 +36,7 @@ #include #include #include +#include int mps_lib_get_EOF(void) @@ -119,7 +120,9 @@ unsigned long mps_lib_telemetry_control(void) unsigned long mask; char buf[256]; char *word; + char *p; char *sep = " "; + char rowName[256]; s = getenv("MPS_TELEMETRY_CONTROL"); if (s == NULL) @@ -130,14 +133,29 @@ unsigned long mps_lib_telemetry_control(void) if (mask != 0) return mask; - /* Split the value at spaces and try to patch the words against the names - of event kinds, enabling them if there's a match. */ + /* copy the envar to a buffer so we can mess with it. */ strncpy(buf, s, sizeof(buf) - 1); buf[sizeof(buf) - 1] = '\0'; + /* downcase it */ + for (p = buf; *p != '\0'; ++p) + *p = (char)tolower(*p); + + /* Split the value at spaces and try to match the words against the names + of event kinds, enabling them if there's a match. */ for (word = strtok(buf, sep); word != NULL; word = strtok(NULL, sep)) { -#define TELEMATCH(X, rowName, rowDoc) \ - if (strcmp(word, #rowName) == 0) \ - mask |= (1ul << EventKind##rowName); + if (strcmp(word, "all") == 0) { + mask = (unsigned long)-1; + printf("All events."); + return mask; + } +#define TELEMATCH(X, name, rowDoc) \ + strncpy(rowName, #name, sizeof(rowName) - 1); \ + rowName[sizeof(rowName) - 1] = '\0'; \ + for (p = rowName; *p != '\0'; ++p) \ + *p = (char)tolower(*p); \ + if (strcmp(word, rowName) == 0) { \ + mask |= (1ul << EventKind##name); \ + printf("Events to include " rowDoc "\n"); } EventKindENUM(TELEMATCH, X) } diff --git a/mps/manual/source/guide/debug.rst b/mps/manual/source/guide/debug.rst index 0ae9040ffae..f76f6276154 100644 --- a/mps/manual/source/guide/debug.rst +++ b/mps/manual/source/guide/debug.rst @@ -188,96 +188,7 @@ since you know that the frame is referenced by the ``car`` of the first pair in the environment, that's the suspect reference. But in a more complex situation this might not yet be clear. In such a situation it can be useful to look at the sequence of events leading -up to the detection of the error, and in order to enable you to do -that, the MPS provides its :ref:`topic-telemetry` feature. - - -.. _guide-debug-telemetry: - -Telemetry ---------- - -In its :term:`cool` :term:`variety`, the MPS is capable of outputting -a configurable stream of events to assist with debugging and -profiling. The exact mechanism by which the telemetry stream is -controlled is in theory configurable via the :ref:`topic-plinth`, but -if you haven't done so then you can set the environment variables -:envvar:`MPS_TELEMETRY_CONTROL` and :envvar:`MPS_TELEMETRY_FILENAME`. -Setting the former to "``65535``" turns on all events, and the default -value for the latter is "``mpsio.log``" which is fine. So let's run -the test case with telemetry turned on:: - - $ gdb ./scheme - GNU gdb 6.3.50-20050815 (Apple version gdb-1820) (Sat Jun 16 02:40:11 UTC 2012) - [...] - (gdb) set environment MPS_TELEMETRY_CONTROL=65535 - (gdb) run - Starting program: example/scheme/scheme - Reading symbols for shared libraries +............................. done - MPS Toy Scheme Example - [...] - 7944, 0> (gc) - [...] - 7968, 1> foo - Assertion failed: (TYPE(frame) == TYPE_PAIR), function lookup_in_frame, file scheme.c, line 1066. - - Program received signal SIGABRT, Aborted. - 0x00007fff91aeed46 in __kill () - -At this point there's still output in the MPS's internal event -buffers, which needs to be flushed. It would be a good idea to add a -call to :c:func:`mps_telemetry_flush` to the error handler, but for -now we can just call it directly from the debugger:: - - (gdb) print mps_telemetry_flush() - $1 = void - -The MPS writes the telemetry to the log in an encoded form for speed. -It can be decoded using the :ref:`eventcnv ` -program:: - - (gdb) shell eventcnv | sort > mpsio.txt - -The ``sort`` is useful because the events are not necessarily written -to the telemetry file in time order, but each event starts with a -timestamp so sorting makes a time series. The decoded events look like -this, with the timestamp in the first column (in units of -:c:type:`mps_clock_t`, typically 1 µs), the event type in the second -column, and then addresses or other data related to the event in the -remaining columns. All numbers are given in hexadecimal. :: - - 00000C0DC0DA69DD395 VMCreate 100128000 100129000 10012A000 - 00000C0DC0DA69E1ACF VMMap 100128000 100129000 10012A000 - 00000C0DC0DA69FF118 Intern 2 Reservoir - 00000C0DC0DA69FF358 Label 1000BD4A8 sym 00002 - 00000C0DC0DA6A04890 PoolInit 100129328 100129000 1000BD4A8 - 00000C0DC0DA6A0C813 VMCreate 10012A000 100300000 100400000 - 00000C0DC0DA6A120B4 VMMap 10012A000 100300000 100301000 - 00000C0DC0DA6A1D0F1 ArenaCreateVM 100129000 100000 100000 - -You can search through the telemetry for events related to particular -addresses of interest. Here we look for events related to the address -of the corrupted ``frame`` object:: - - (gdb) frame 3 - #3 0x0000000100003f55 in lookup_in_frame (frame=0x1003fa7d0, symbol=0x1003faf20) at scheme.c:1066 - 1066 assert(TYPE(frame) == TYPE_PAIR); - (gdb) print frame - $2 = (obj_t) 0x1003fa7d0 - (gdb) shell grep -i 1003fa7d0 mpsio.txt || echo not found - not found - -There are no events related to this address, so in particular this -address was never fixed (no ``TraceFix`` event). This should be enough -of a clue to track down the cause. - -.. note:: - - You may find it useful to add the command:: - - set environment MPS_TELEMETRY_CONTROL=65535 - - to your ``.gdbinit``. +up to the detection of the error. See :ref:`topic-telemetry`. .. _guide-debug-size: diff --git a/mps/manual/source/topic/telemetry.rst b/mps/manual/source/topic/telemetry.rst index baa08e43703..eb03b01fe0e 100644 --- a/mps/manual/source/topic/telemetry.rst +++ b/mps/manual/source/topic/telemetry.rst @@ -31,12 +31,97 @@ John McCarthy described the first on-line demonstration of thought we were victims of a practical joker. +Introduction +------------ -Typical uses of telemetry labels include: +In its :term:`cool` :term:`variety`, the MPS is capable of outputting +a configurable stream of events to assist with debugging and +profiling. -- Label pools with a human-meaningful name; +The selection of events that appear in the stream is controlled by the +environment variable :envvar:`MPS_TELEMETRY_CONTROL` (by default +none), and the stream is written to the file named by the environment +variable :envvar:`MPS_TELEMETRY_FILENAME` (by default ``mpsio.log``). -- Label allocated objects with their type or class. + +Example +------- + +Here's an example of turning on telemetry in the debugger and then +encountering a corrupted object:: + + $ gdb ./scheme + GNU gdb 6.3.50-20050815 (Apple version gdb-1820) (Sat Jun 16 02:40:11 UTC 2012) + [...] + (gdb) set environment MPS_TELEMETRY_CONTROL=all + (gdb) run + Starting program: example/scheme/scheme + Reading symbols for shared libraries +............................. done + MPS Toy Scheme Example + [...] + 7944, 0> (gc) + [...] + 7968, 1> foo + Assertion failed: (TYPE(frame) == TYPE_PAIR), function lookup_in_frame, file scheme.c, line 1066. + + Program received signal SIGABRT, Aborted. + 0x00007fff91aeed46 in __kill () + +At this point there's still output in the MPS's internal event +buffers, which needs to be flushed. It would be a good idea to add a +call to :c:func:`mps_telemetry_flush` to the error handler, but for +now we can just call it directly from the debugger:: + + (gdb) print mps_telemetry_flush() + $1 = void + +The MPS writes the telemetry to the log in an encoded form for speed. +It can be decoded using the :ref:`eventcnv ` +program:: + + (gdb) shell eventcnv | sort > mpsio.txt + +The ``sort`` is useful because the events are not necessarily written +to the telemetry file in time order, but each event starts with a +timestamp so sorting makes a time series. The decoded events look like +this, with the timestamp in the first column (in units of +:c:type:`mps_clock_t`, typically 1 µs), the event type in the second +column, and then addresses or other data related to the event in the +remaining columns. All numbers are given in hexadecimal. :: + + 000AE03973336E3C 2B 1003FC000 1003FD000 1003FE000 + 000AE0397333BC6D 2D 1003FC000 1003FD000 1003FE000 + 000AE0397334DF9F 1A 2 "Reservoir" + 000AE0397334E0A0 1B 1078C85B8 2 + 000AE03973352375 15 1003FD328 1003FD000 1078C85B8 + 000AE039733592F9 2B 1003FE000 1003FF000 10992F000 + 000AE0397335C8B5 2D 1003FE000 1003FF000 107930000 + 000AE03973361D5A 5 1003FD000 2000000 2000000 + +You can search through the telemetry for events related to particular +addresses of interest. + +In the example, we might look for events related to the address of the +corrupted ``frame`` object:: + + (gdb) frame 3 + #3 0x0000000100003f55 in lookup_in_frame (frame=0x1003fa7d0, symbol=0x1003faf20) at scheme.c:1066 + 1066 assert(TYPE(frame) == TYPE_PAIR); + (gdb) print frame + $2 = (obj_t) 0x1003fa7d0 + (gdb) shell grep -i 1003fa7d0 mpsio.txt || echo not found + not found + +There are no events related to this address, so in particular this +address was never fixed (no ``TraceFix`` event). + +.. note:: + + You may find it useful to add the command:: + + set environment MPS_TELEMETRY_CONTROL=all + + to your ``.gdbinit``. Event categories @@ -73,14 +158,16 @@ telemetry feature. If its value can be interpreted as a number, then this number represents the set of event categories as a :term:`bitmap`. For - example, this turns on event categories numbered 0 to 15:: + example, this turns on the ``Pool`` and ``Seg`` event categories:: - MPS_TELEMETRY_CONTROL=65535 + MPS_TELEMETRY_CONTROL=6 Otherwise, the value is split into words at spaces, and any word that names an event category turns it on. For example:: - MPS_TELEMETRY_CONTROL="Arena Pool Trace" + MPS_TELEMETRY_CONTROL="arena pool trace" + + The special event category ``all`` turns on all events. .. note:: @@ -111,26 +198,6 @@ standard output) a representation of each event in the stream. The name of the file containing the telemetry stream to decode. Defaults to ``mpsio.log``. - -.. option:: -S - - Format output human-readably. This is the default output style. - For example:: - - 000007DC7DC1655516E TraceFix 7FFF583001D0 7FFF583000D8 107AFAB20 1 - -.. option:: -SL - - Format output as S-expressions for consumption by :term:`Lisp`. - For example:: - - (000007DC7DC1655516E TraceFix 7FFF583001D0 7FFF583000D8 107AFAB20 1) - -.. option:: -SC - - Format output as CSV (comma-separated values). For example:: - - 000007DC7DC1655516E, 38, 140734672929232, 140734672928984, 4423920416, 1 .. option:: -h @@ -193,6 +260,16 @@ Telemetry interface even try calling this from a debugger after a problem. +Telemetry labels +---------------- + +Typical uses of telemetry labels include: + +- Label pools with a human-meaningful name; + +- Label allocated objects with their type or class. + + .. c:function:: mps_word_t mps_telemetry_intern(char *label) Registers a string with the MPS, and receives a :term:`telemetry