Changeset: 2c21c59aa75f for MonetDB
URL: https://dev.monetdb.org/hg/MonetDB/rev/2c21c59aa75f
Modified Files:
clients/Tests/exports.stable.out
monetdb5/mal/mal.h
monetdb5/mal/mal_profiler.c
monetdb5/mal/mal_profiler.h
monetdb5/mal/mal_runtime.c
monetdb5/mal/mal_runtime.h
Branch: default
Log Message:
Fixed data race in runtimeProfilerBegin and runtimeProfilerExit.
We no longer keep track of instruction timings inside the instruction
struct since that was getting changed by multiple threads executing the
same instruction. This probably also means the value is more accurate
when multiple threads are executing the same instruction.
diffs (203 lines):
diff --git a/clients/Tests/exports.stable.out b/clients/Tests/exports.stable.out
--- a/clients/Tests/exports.stable.out
+++ b/clients/Tests/exports.stable.out
@@ -1276,7 +1276,6 @@ void slash_2_dir_sep(str fname);
const char *sliceRef;
const char *sortRef;
const char *sortReverseRef;
-void sqlProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci);
const char *sqlRef;
const char *sqlcatalogRef;
str startProfiler(Client cntxt);
diff --git a/monetdb5/mal/mal.h b/monetdb5/mal/mal.h
--- a/monetdb5/mal/mal.h
+++ b/monetdb5/mal/mal.h
@@ -151,8 +151,6 @@ typedef struct {
MALfcn fcn; /* resolved function
address */
struct MALBLK *blk; /* resolved MAL function
address */
/* inline statistics */
- lng clock; /* when the last call
was started */
- lng ticks; /* total micro seconds
spent in last call */
lng wbytes; /* number of bytes
produced in last instruction */
/* the core admin */
const char *modname; /* module context, reference into
namespace */
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
@@ -270,11 +270,10 @@ format_val2json(const ValPtr res) {
}
static str
-prepareMalEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci)
+prepareMalEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, lng
clk, lng ticks)
{
struct logbuf logbuf;
str c;
- lng clk;
uint64_t mclk;
bool ok;
const char *algo = MT_thread_getalgorithm();
@@ -291,7 +290,6 @@ prepareMalEvent(Client cntxt, MalBlkPtr
logbuf = (struct logbuf) {0};
- clk = pci->clock;
mclk = (uint64_t)clk - ((uint64_t)startup_time.tv_sec*1000000 -
(uint64_t)startup_time.tv_usec);
/* make profile event tuple */
if (!logadd(&logbuf,
@@ -318,7 +316,7 @@ prepareMalEvent(Client cntxt, MalBlkPtr
if ((pci->token < FCNcall || pci->token > PATcall) &&
!logadd(&logbuf, ",\"operator\":\"%s\"",
operatorName(pci->token)))
goto cleanup_and_exit;
- if (!logadd(&logbuf, ",\"usec\":"LLFMT, pci->ticks))
+ if (!logadd(&logbuf, ",\"usec\":"LLFMT, ticks))
goto cleanup_and_exit;
if (algo && !logadd(&logbuf, ",\"algorithm\":\"%s\"", algo))
goto cleanup_and_exit;
@@ -656,7 +654,7 @@ profilerEvent(MalEvent *me, NonMalEvent
MT_lock_unset(&mal_profileLock);
return; /* minimal mode */
}
- event = prepareMalEvent(me->cntxt, me->mb, me->stk,
me->pci);
+ event = prepareMalEvent(me->cntxt, me->mb, me->stk,
me->pci, me->clk, me->duration);
}
if (me == NULL && nme != NULL && nme->phase != MAL_ENGINE) {
event = prepareNonMalEvent(nme->cntxt, nme->phase,
nme->clk, nme->tid, nme->ts, nme->state, nme->duration);
@@ -720,15 +718,15 @@ openProfilerStream(Client cntxt, int m)
MT_sleep_ms(200);
for (j = 0; j <THREADS; j++){
- Client c = 0; MalBlkPtr m = 0; MalStkPtr s = 0; InstrPtr p = 0;
- c = workingset[j].cntxt;
- m = workingset[j].mb;
- s = workingset[j].stk;
- p = workingset[j].pci;
+ Client c = workingset[j].cntxt;
+ MalBlkPtr m = workingset[j].mb;
+ MalStkPtr s = workingset[j].stk;
+ InstrPtr p = workingset[j].pci;
+ lng t = workingset[j].clock;
if (c && m && s && p) {
- /* show the event assuming the quadruple is aligned*/
+ /* show the event assuming the quintuple is aligned*/
MT_lock_unset(&mal_profileLock);
- profilerEvent(&(struct MalEvent) {c, m, s, p},
+ profilerEvent(&(struct MalEvent) {c, m, s, p, t, 0},
NULL);
MT_lock_set(&mal_profileLock);
}
@@ -909,7 +907,7 @@ cleanupTraces(Client cntxt)
}
void
-sqlProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci)
+sqlProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, lng
clk, lng ticks)
{
str stmt, c, ev;
int errors = 0;
@@ -926,7 +924,7 @@ sqlProfilerEvent(Client cntxt, MalBlkPtr
c++;
*/
- ev = prepareMalEvent(cntxt, mb, stk, pci);
+ ev = prepareMalEvent(cntxt, mb, stk, pci, clk, ticks);
// keep it a short transaction
MT_lock_set(&mal_profileLock);
if (cntxt->profticks == NULL) {
@@ -934,7 +932,7 @@ sqlProfilerEvent(Client cntxt, MalBlkPtr
GDKfree(stmt);
return;
}
- errors += BUNappend(cntxt->profticks, &pci->ticks, false) !=
GDK_SUCCEED;
+ errors += BUNappend(cntxt->profticks, &ticks, false) != GDK_SUCCEED;
errors += BUNappend(cntxt->profstmt, c, false) != GDK_SUCCEED;
errors += BUNappend(cntxt->profevents, ev ? ev : str_nil, false) !=
GDK_SUCCEED;
if (errors > 0) {
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
@@ -50,6 +50,8 @@ typedef struct MalEvent {
MalBlkPtr mb;
MalStkPtr stk;
InstrPtr pci;
+ lng clk; /* end time */
+ lng duration;
} MalEvent;
mal_export int profilerStatus;
@@ -60,7 +62,6 @@ mal_export str openProfilerStream(Client
mal_export str closeProfilerStream(Client cntxt);
mal_export void profilerEvent(MalEvent *me, NonMalEvent *nme);
-mal_export void sqlProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk,
InstrPtr pci);
mal_export oid runtimeProfileSetTag(Client cntxt);
mal_export str startProfiler(Client cntxt);
diff --git a/monetdb5/mal/mal_runtime.c b/monetdb5/mal/mal_runtime.c
--- a/monetdb5/mal/mal_runtime.c
+++ b/monetdb5/mal/mal_runtime.c
@@ -336,6 +336,7 @@ void
runtimeProfileBegin(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci,
RuntimeProfile prof)
{
int tid = THRgettid();
+ lng clk = GDKusec();
assert(pci);
/* keep track on the instructions taken in progress for stethoscope*/
@@ -347,16 +348,18 @@ runtimeProfileBegin(Client cntxt, MalBlk
workingset[tid].mb = mb;
workingset[tid].stk = stk;
workingset[tid].pci = pci;
+ workingset[tid].clock = clk;
MT_lock_unset(&mal_profileLock);
} else {
workingset[tid].cntxt = cntxt;
workingset[tid].mb = mb;
workingset[tid].stk = stk;
workingset[tid].pci = pci;
+ workingset[tid].clock = clk;
}
}
/* always collect the MAL instruction execution time */
- pci->clock = prof->ticks = GDKusec();
+ prof->ticks = clk;
}
/* At the end of each MAL stmt */
@@ -378,15 +381,11 @@ runtimeProfileExit(Client cntxt, MalBlkP
}
}
- /* always collect the MAL instruction execution time */
- pci->clock = ticks;
- pci->ticks = ticks - prof->ticks;
-
if (profilerStatus > 0 )
- profilerEvent(&(struct MalEvent) {cntxt, mb, stk, pci},
+ profilerEvent(&(struct MalEvent) {cntxt, mb, stk, pci, ticks,
ticks - prof->ticks},
NULL);
if (cntxt->sqlprofiler)
- sqlProfilerEvent(cntxt, mb, stk, pci);
+ sqlProfilerEvent(cntxt, mb, stk, pci, ticks, ticks -
prof->ticks);
if (profilerStatus < 0) {
/* delay profiling until you encounter start of MAL function */
if (getInstrPtr(mb,0) == pci)
diff --git a/monetdb5/mal/mal_runtime.h b/monetdb5/mal/mal_runtime.h
--- a/monetdb5/mal/mal_runtime.h
+++ b/monetdb5/mal/mal_runtime.h
@@ -62,6 +62,7 @@ typedef struct WORKINGSET{
MalBlkPtr mb;
MalStkPtr stk;
InstrPtr pci;
+ lng clock; /* start time */
} Workingset;
extern Workingset workingset[THREADS];
@@ -72,6 +73,7 @@ extern void runtimeProfileBegin(Client c
extern void runtimeProfileExit(Client cntxt, MalBlkPtr mb, MalStkPtr stk,
InstrPtr pci, RuntimeProfile prof);
extern lng getVolume(MalStkPtr stk, InstrPtr pci, int rd);
extern lng getBatSpace(BAT *b);
+extern void sqlProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk,
InstrPtr pci, lng clk, lng ticks);
extern QueryQueue QRYqueue;
extern UserStats USRstats;
_______________________________________________
checkin-list mailing list -- [email protected]
To unsubscribe send an email to [email protected]
