Changeset: 031bcd3b9fc6 for MonetDB URL: https://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=031bcd3b9fc6 Modified Files: monetdb5/mal/mal_profiler.c monetdb5/mal/mal_profiler.h monetdb5/modules/mal/profiler.c monetdb5/modules/mal/profiler.h monetdb5/modules/mal/profiler.mal sql/scripts/46_profiler.sql Branch: default Log Message:
Introduce sync events MonetDB reports time since an epoch, which roughly corresponds to the start time of the server. When we are working with distributed queries (remote tables), we need to profile two different Monet servers we probably have different start times. In order to be able to correlate different time lines from different servers the sync event contains the current internal clock value and the number of microseconds since the UNIX Epoch. This assumes that gettimeofday will produce consistent results in different servers, and while this assumption might be violated in practice, the only side effect is that profiling will be inaccurate. diffs (175 lines): diff --git a/monetdb5/mal/mal_profiler.c b/monetdb5/mal/mal_profiler.c --- a/monetdb5/mal/mal_profiler.c +++ b/monetdb5/mal/mal_profiler.c @@ -8,11 +8,11 @@ /* (c) M.L. Kersten * Performance tracing - * The stethoscope/tachograph and tomograph performance monitors have exclusive access - * to a single event stream, which avoids concurrency conflicts amongst clients. + * The stethoscope/tachograph and tomograph performance monitors have exclusive access + * to a single event stream, which avoids concurrency conflicts amongst clients. * It also avoid cluthered event records on the stream. Since this event stream is owned - * by a client, we should ensure that the profiler is automatically - * reset once the owner leaves. + * by a client, we should ensure that the profiler is automatically + * reset once the owner leaves. */ #include "monetdb_config.h" #include "mal_function.h" @@ -116,7 +116,7 @@ truncate_string(char *inp) return ret; } -/* JSON rendering method of performance data. +/* JSON rendering method of performance data. * The eventparser may assume this layout for ease of parsing EXAMPLE: { @@ -421,7 +421,7 @@ getCPULoad(char cpuload[BUFSIZ]){ corestat[cpu].system = system; corestat[cpu].idle = idle; corestat[cpu].iowait = iowait; - } + } skip: while (*s && *s != '\n') s++; @@ -502,7 +502,7 @@ profilerEvent(MalBlkPtr mb, MalStkPtr st /* The first scheme dumps the events * on a stream (and in the pool) - * The mode encodes two flags: + * The mode encodes two flags: * - showing all running instructions * - single line json */ @@ -533,13 +533,15 @@ openProfilerStream(stream *fd, int mode) if( (mode & PROFSHOWRUNNING) > 0){ for (i = 0; i < MAL_MAXCLIENTS; i++) { c = mal_clients+i; - if ( c->active ) + if ( c->active ) for(j = 0; j <THREADS; j++) if( c->inprogress[j].mb) /* show the event */ profilerEvent(c->inprogress[j].mb, c->inprogress[j].stk, c->inprogress[j].pci, 1, c->username); } } + /* Syncronize at start up */ + syncEvent(); return MAL_SUCCEED; } @@ -618,7 +620,7 @@ stopTrace(str path) offlinestore =0; } MT_lock_unset(&mal_profileLock ); - + malProfileMode = eventstream != NULL; sqlProfiling = FALSE; return MAL_SUCCEED; @@ -817,7 +819,7 @@ initTrace(void) TRACE_id_minflt == NULL || TRACE_id_majflt == NULL || TRACE_id_nvcsw == NULL || - TRACE_id_thread == NULL + TRACE_id_thread == NULL ) _cleanupProfiler(); else @@ -1079,3 +1081,30 @@ void initHeartbeat(void) } } +str +syncEvent(void) +{ + char logbuffer[LOGLEN], *logbase; + int loglen; + struct timeval curr_time; + lng usec = GDKusec(); + uint64_t clock_time; + + gettimeofday(&curr_time, NULL); + clock_time = curr_time.tv_sec*1000000 + (curr_time.tv_usec == -1 ? 0 : curr_time.tv_usec); + + lognew(); + logadd("{%s", prettify); + logadd("\"source\":\"sync\",%s", prettify); + if(mal_session_uuid) + logadd("\"session\":\"%s\",%s", mal_session_uuid, prettify); + // the state field is not really needed, but marvin 1.0 explicitly + // searches for it. + logadd("\"state\":\"callback\",%s", prettify); + logadd("\"clk\":"LLFMT",%s", usec, prettify); + logadd("\"time\":%"PRIu64",%s", clock_time, prettify); + logadd("}\n"); + logjsonInternal(logbuffer); + + return MAL_SUCCEED; +} diff --git a/monetdb5/mal/mal_profiler.h b/monetdb5/mal/mal_profiler.h --- a/monetdb5/mal/mal_profiler.h +++ b/monetdb5/mal/mal_profiler.h @@ -56,4 +56,6 @@ mal_export lng getDiskWrites(void); mal_export lng getUserTime(void); mal_export lng getSystemTime(void); mal_export void profilerGetCPUStat(lng *user, lng *nice, lng *sys, lng *idle, lng *iowait); + +mal_export str syncEvent(void); #endif diff --git a/monetdb5/modules/mal/profiler.c b/monetdb5/modules/mal/profiler.c --- a/monetdb5/modules/mal/profiler.c +++ b/monetdb5/modules/mal/profiler.c @@ -83,7 +83,7 @@ CMDstartTrace(void *res) } // if you haven't started the stethoscope -// then the output is saved in a file +// then the output is saved in a file str CMDstartTracePath(void *res, str *path) { @@ -216,3 +216,10 @@ CMDcpuloadPercentage(int *cycles, int *i } return MAL_SUCCEED; } + +str +CMDsyncEvent(void *ret) +{ + (void)ret; + return syncEvent(); +} diff --git a/monetdb5/modules/mal/profiler.h b/monetdb5/modules/mal/profiler.h --- a/monetdb5/modules/mal/profiler.h +++ b/monetdb5/modules/mal/profiler.h @@ -48,4 +48,6 @@ mal_export str CMDgetUserTime(lng *ret); mal_export str CMDgetSystemTime(lng *ret); mal_export str CMDcpustats(lng *user, lng *nice, lng *sys, lng *idle, lng *iowait); mal_export str CMDcpuloadPercentage(int *cycles, int *io, lng *user, lng *nice, lng *sys, lng *idle, lng *iowait); + +mal_export str CMDsyncEvent(void *ret); #endif /* _PROFILER_*/ diff --git a/monetdb5/modules/mal/profiler.mal b/monetdb5/modules/mal/profiler.mal --- a/monetdb5/modules/mal/profiler.mal +++ b/monetdb5/modules/mal/profiler.mal @@ -83,3 +83,7 @@ comment "Extract cpu statistics from the command cpuload(user:lng, nice:lng, sys:lng,idle:lng,iowait:lng)(cycles:int,io:int) address CMDcpuloadPercentage comment "Calculate the average cpu load percentage and io waiting times"; + +command sync() +address CMDsyncEvent +comment "Generate a syncronization event" diff --git a/sql/scripts/46_profiler.sql b/sql/scripts/46_profiler.sql --- a/sql/scripts/46_profiler.sql +++ b/sql/scripts/46_profiler.sql @@ -13,3 +13,5 @@ create procedure profiler.stop() externa create procedure profiler.setheartbeat(beat int) external name profiler.setheartbeat; create function profiler.getlimit() returns integer external name profiler.getlimit; create procedure profiler.setlimit(lim integer) external name profiler.setlimit; + +create procedure profiler.sync() external name profiler.sync; _______________________________________________ checkin-list mailing list checkin-list@monetdb.org https://www.monetdb.org/mailman/listinfo/checkin-list