Changeset: 52094df60b35 for MonetDB
URL: https://dev.monetdb.org/hg/MonetDB/rev/52094df60b35
Modified Files:
monetdb5/mal/mal_profiler.c
monetdb5/mal/mal_profiler.h
sql/backends/monet5/sql.c
sql/backends/monet5/sql_scenario.c
sql/include/sql_catalog.h
sql/server/sql_mvc.c
sql/storage/sql_storage.h
sql/storage/store.c
Branch: sql_profiler
Log Message:
Log both start and end events for transactions and add client and tag info to
them.
diffs (231 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
@@ -172,32 +172,32 @@ logadd(struct logbuf *logbuf, const char
}
static str
-prepareNonMalEvent(Client cntxt, str phase, ulng clk, ulng *tid, int state,
ulng duration)
+prepareNonMalEvent(Client cntxt, str phase, ulng clk, ulng *tid, ulng *ts, int
state, ulng duration)
{
oid* tag = NULL;
- int sessionid = -1;
str query = NULL;
struct logbuf logbuf = {0};
uint64_t mclk = (uint64_t)clk -
((uint64_t)startup_time.tv_sec*1000000 -
(uint64_t)startup_time.tv_usec);
- if (cntxt) {
- sessionid = cntxt->idx;
- if (cntxt->curprg)
- tag = &cntxt->curprg->def->tag;
- if (cntxt->query)
- query = mal_quote(cntxt->query, strlen(cntxt->query));
- }
+ assert(cntxt);
+ int sessionid = cntxt->idx;
+ if (cntxt->curprg)
+ tag = &cntxt->curprg->def->tag;
+ if (cntxt->query)
+ query = mal_quote(cntxt->query, strlen(cntxt->query));
- if (sessionid != -1 && !logadd(&logbuf, "{\"sessionid\":\"%d\"",
sessionid))
+ if (!logadd(&logbuf, "{\"sessionid\":\"%d\"", sessionid))
goto cleanup_and_exit;
if (!logadd(&logbuf, ", \"clk\":"ULLFMT"", mclk))
goto cleanup_and_exit;
if (!logadd(&logbuf, ", \"thread\":%d, \"phase\":\"%s\"",
THRgettid(), phase))
goto cleanup_and_exit;
- if (tid && !logadd(&logbuf, ", \"transactionid\":"ULLFMT, *tid))
+ if (tid && !logadd(&logbuf, ", \"tid\":"ULLFMT, *tid))
+ goto cleanup_and_exit;
+ if (ts && !logadd(&logbuf, ", \"ts\":"ULLFMT, *ts))
goto cleanup_and_exit;
if (tag && !logadd(&logbuf, ", \"tag\":"OIDFMT, *tag))
goto cleanup_and_exit;
@@ -630,7 +630,7 @@ profilerEvent(MalEvent me, NonMalEvent n
event = prepareMalEvent(me.cntxt, me.mb, me.stk,
me.pci);
}
if (me.mb == NULL && nme.phase != NULL) {
- event = prepareNonMalEvent(nme.cntxt, nme.phase,
nme.clk, nme.tid, nme.state, nme.duration);
+ event = prepareNonMalEvent(nme.cntxt, nme.phase,
nme.clk, nme.tid, nme.ts, nme.state, nme.duration);
}
if (event) {
logjsonInternal(event, true);
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
@@ -25,6 +25,7 @@ typedef struct NonMalEvent {
Client cntxt;
ulng clk;
ulng* tid;
+ ulng* ts;
int state;
ulng duration;
} NonMalEvent;
diff --git a/sql/backends/monet5/sql.c b/sql/backends/monet5/sql.c
--- a/sql/backends/monet5/sql.c
+++ b/sql/backends/monet5/sql.c
@@ -135,7 +135,7 @@ sql_symbol2relation(backend *be, symbol
if(malProfileMode > 0 )
profilerEvent((struct MalEvent) {0},
(struct NonMalEvent)
- {"sql_to_rel", c, Tend, NULL,
rel?0:1, Tend-Tbegin});
+ {"sql_to_rel", c, Tend, NULL, NULL,
rel?0:1, Tend-Tbegin});
storage_based_opt = value_based_opt && rel && !is_ddl(rel->op);
Tbegin = Tend;
@@ -151,7 +151,7 @@ sql_symbol2relation(backend *be, symbol
if(malProfileMode > 0)
profilerEvent((struct MalEvent) {0},
(struct NonMalEvent)
- {"rel_opt", c, Tend, NULL, rel?0:1,
be->reloptimizer});
+ {"rel_opt", c, Tend, NULL, NULL,
rel?0:1, be->reloptimizer});
return rel;
}
diff --git a/sql/backends/monet5/sql_scenario.c
b/sql/backends/monet5/sql_scenario.c
--- a/sql/backends/monet5/sql_scenario.c
+++ b/sql/backends/monet5/sql_scenario.c
@@ -980,6 +980,10 @@ SQLparser(Client c)
m = be->mvc;
m->type = Q_PARSE;
if (be->language != 'X') {
+ // generate and set the tag in the mal block of the clients
current program.
+ tag = runtimeProfileSetTag(c);
+ assert(tag == c->curprg->def->tag);
+ (void) tag;
if ((msg = SQLtrans(m)) != MAL_SUCCEED) {
c->mode = FINISHCLIENT;
return msg;
@@ -1098,11 +1102,6 @@ SQLparser(Client c)
goto finalize;
}
- // generate and set the tag in the mal block of the clients current
program.
- tag = runtimeProfileSetTag(c);
- assert(tag == c->curprg->def->tag);
- (void) tag;
-
Tbegin = GDKusec();
if ((err = sqlparse(m)) ||
@@ -1135,7 +1134,7 @@ SQLparser(Client c)
if(malProfileMode > 0) {
profilerEvent((struct MalEvent) {0},
(struct NonMalEvent)
- {"sql_parser", c, Tend, NULL,
c->query?0:1, Tend-Tbegin});
+ {"sql_parser", c, Tend, NULL, NULL,
c->query?0:1, Tend-Tbegin});
}
if (c->query == NULL) {
@@ -1204,7 +1203,7 @@ SQLparser(Client c)
if(malProfileMode > 0)
profilerEvent((struct MalEvent) {0},
(struct NonMalEvent)
- {"rel_to_mal", c,
Tend, NULL, c->query?0:1, Tend-Tbegin});
+ {"rel_to_mal", c,
Tend, NULL, NULL, c->query?0:1, Tend-Tbegin});
} else {
char *q_copy = sa_strdup(m->sa, c->query);
@@ -1288,7 +1287,7 @@ SQLparser(Client c)
if(malProfileMode > 0)
profilerEvent((struct MalEvent) {0},
(struct NonMalEvent)
- {"mal_opt", c, Tend,
NULL, msg==MAL_SUCCEED?0:1, Tend-Tbegin});
+ {"mal_opt", c, Tend,
NULL, NULL, msg==MAL_SUCCEED?0:1, Tend-Tbegin});
if (msg != MAL_SUCCEED) {
str other = c->curprg->def->errors;
/* In debugging mode you may want to assess
what went wrong in the optimizers*/
diff --git a/sql/include/sql_catalog.h b/sql/include/sql_catalog.h
--- a/sql/include/sql_catalog.h
+++ b/sql/include/sql_catalog.h
@@ -308,7 +308,6 @@ typedef struct sql_trans {
ulng ts; /* transaction start timestamp */
ulng tid; /* transaction id */
- ulng clk_start; /* transaction start timestamp in microseconds */
sql_store store; /* keep link into the global store */
MT_Lock lock; /* lock protecting concurrent writes to the
changes list */
diff --git a/sql/server/sql_mvc.c b/sql/server/sql_mvc.c
--- a/sql/server/sql_mvc.c
+++ b/sql/server/sql_mvc.c
@@ -125,14 +125,14 @@ mvc_fix_depend(mvc *m, sql_column *depid
}
static void
-profiler_event_wrapper(str phase, lng clk, ulng *tid, int state, lng usec)
+profiler_event_wrapper(str phase, lng clk, ulng *tid, ulng *ts, int state, lng
usec)
{
Client c = getClientContext();
if(malProfileMode > 0)
profilerEvent((struct MalEvent) {0},
(struct NonMalEvent)
- {phase, c, clk, tid, state, usec});
+ {phase, c, clk, tid, ts, state,
usec});
}
sql_store
@@ -489,8 +489,6 @@ mvc_trans(mvc *m)
TRC_INFO(SQL_TRANS, "Starting transaction\n");
res = sql_trans_begin(m->session);
- m->session->tr->clk_start = GDKusec();
-
if (m->qc && (res || err)) {
int seqnr = m->qc->id;
if (m->qc)
diff --git a/sql/storage/sql_storage.h b/sql/storage/sql_storage.h
--- a/sql/storage/sql_storage.h
+++ b/sql/storage/sql_storage.h
@@ -331,7 +331,7 @@ extern res_table *res_tables_remove(res_
sql_export void res_tables_destroy(res_table *results);
extern res_table *res_tables_find(res_table *results, int res_id);
-typedef void (*profiler_event_wrapper_fptr) (str phase, lng clk, ulng *tid,
int state, lng usec);
+typedef void (*profiler_event_wrapper_fptr) (str phase, lng clk, ulng *tid,
ulng *ts, int state, lng usec);
extern struct sqlstore *store_init(int debug, store_type store, int readonly,
int singleuser, profiler_event_wrapper_fptr event_wrapper);
extern void store_exit(struct sqlstore *store);
diff --git a/sql/storage/store.c b/sql/storage/store.c
--- a/sql/storage/store.c
+++ b/sql/storage/store.c
@@ -3680,7 +3680,7 @@ sql_trans_rollback(sql_trans *tr, bool c
}
Tend = GDKusec();
- store->profiler_event_wrapper("rollback", Tend, &tr->tid, 0,
Tend-Tbegin);
+ store->profiler_event_wrapper("rollback", Tend, &tr->tid, NULL, 0,
Tend-Tbegin);
}
sql_trans *
@@ -4051,7 +4051,7 @@ sql_trans_commit(sql_trans *tr)
ok = clean_predicates_and_propagate_to_parent(tr);
Tend = GDKusec();
- store->profiler_event_wrapper("commit", Tend, &tr->tid, ok==LOG_OK?0:1,
Tend-Tbegin);
+ store->profiler_event_wrapper("commit", Tend, &tr->tid, NULL, ok,
Tend-Tbegin);
return (ok==LOG_OK)?SQL_OK:SQL_ERR;
}
@@ -7056,6 +7056,7 @@ sql_trans_begin(sql_session *s)
TRC_DEBUG(SQL_STORE, "Exit sql_trans_begin for transaction: " ULLFMT
"\n", tr->tid);
store_unlock(store);
s->status = tr->status = 0;
+ store->profiler_event_wrapper("start transaction", GDKusec(),
&s->tr->tid, &s->tr->ts, 0, 0);
return 0;
}
@@ -7089,7 +7090,7 @@ sql_trans_end(sql_session *s, int ok)
assert(list_length(store->active) == (int)
ATOMIC_GET(&store->nr_active));
store_unlock(store);
lng Tend = GDKusec();
- store->profiler_event_wrapper("transaction", Tend, &s->tr->tid,
ok==LOG_OK?0:1, Tend-(s->tr->clk_start));
+ store->profiler_event_wrapper("end transaction", Tend, &s->tr->tid,
&s->tr->ts, ok==SQL_OK?0:1, 0);
return ok;
}
_______________________________________________
checkin-list mailing list -- [email protected]
To unsubscribe send an email to [email protected]
