Changeset: d7ee19a20d57 for MonetDB
URL: https://dev.monetdb.org/hg/MonetDB/rev/d7ee19a20d57
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: Jul2021_prof_ext
Log Message:
Log both start and end events for transactions and add client and tag info to
them.
diffs (240 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
@@ -170,32 +170,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;
@@ -609,7 +609,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});
Tbegin = Tend;
if (rel)
@@ -152,7 +152,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
@@ -995,6 +995,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;
@@ -1113,11 +1117,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)) ||
@@ -1150,7 +1149,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) {
@@ -1209,7 +1208,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);
@@ -1283,7 +1282,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
@@ -302,7 +302,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
@@ -124,14 +124,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
@@ -484,8 +484,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
@@ -309,8 +309,8 @@ 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 (*generic_event_wrapper_fptr) (str face, ulng tid, lng usec, lng
clk, int rc);
-extern struct sqlstore *store_init(int debug, store_type store, int readonly,
int singleuser, generic_event_wrapper_fptr event_wrapper);
+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);
extern void store_suspend_log(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
@@ -3584,9 +3584,9 @@ sql_trans_rollback(sql_trans *tr, bool c
list_destroy(tr->depchanges);
tr->depchanges = NULL;
}
- Tend = GDKusec();
- store->generic_event_wrapper("rollback",
- tr->tid,
Tend-Tbegin, Tend, 0);
+
+ Tend = GDKusec();
+ store->profiler_event_wrapper("rollback", Tend, &tr->tid, NULL, 0,
Tend-Tbegin);
}
sql_trans *
@@ -3938,8 +3938,7 @@ sql_trans_commit(sql_trans *tr)
ok = clean_predicates_and_propagate_to_parent(tr);
Tend = GDKusec();
- store->generic_event_wrapper("commit",
- tr->tid,
Tend-Tbegin, Tend, (ok == LOG_OK)? SQL_OK : SQL_ERR);
+ store->profiler_event_wrapper("commit", Tend, &tr->tid, NULL, ok,
Tend-Tbegin);
return (ok==LOG_OK)?SQL_OK:SQL_ERR;
}
@@ -6874,6 +6873,8 @@ sql_trans_begin(sql_session *s)
s->status = 0;
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;
}
@@ -6906,7 +6907,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->generic_event_wrapper("transaction",
- s->tr->tid,
Tend-(s->tr->clk_start), Tend, (ok == LOG_OK)? SQL_OK : SQL_ERR);
+ 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]
