Changeset: cd2abaa07bf5 for MonetDB URL: https://dev.monetdb.org/hg/MonetDB/rev/cd2abaa07bf5 Modified Files: clients/Tests/MAL-signatures.stable.out clients/Tests/MAL-signatures.stable.out.int128 monetdb5/mal/mal_client.h monetdb5/mal/mal_profiler.c sql/backends/monet5/sql.c sql/backends/monet5/sql.mal sql/backends/monet5/sql_upgrades.c sql/scripts/16_tracelog.sql sql/test/emptydb/Tests/check.stable.out sql/test/emptydb/Tests/check.stable.out.32bit sql/test/emptydb/Tests/check.stable.out.int128 Branch: default Log Message:
Add the profiler exit event to the tracelog() diffs (truncated from 505 to 300 lines): diff --git a/clients/Tests/MAL-signatures.stable.out b/clients/Tests/MAL-signatures.stable.out --- a/clients/Tests/MAL-signatures.stable.out +++ b/clients/Tests/MAL-signatures.stable.out @@ -9275,7 +9275,7 @@ stdout of test 'MAL-signatures` in direc [ "sql", "droporderindex", "unsafe pattern sql.droporderindex(X_0:str, X_1:str, X_2:str):void ", "sql_droporderindex;", "" ] [ "sql", "dump_cache", "pattern sql.dump_cache() (X_0:bat[:str], X_1:bat[:int]) ", "dump_cache;", "" ] [ "sql", "dump_opt_stats", "pattern sql.dump_opt_stats() (X_0:bat[:str], X_1:bat[:int]) ", "dump_opt_stats;", "" ] -[ "sql", "dump_trace", "pattern sql.dump_trace() (X_0:bat[:lng], X_1:bat[:str]) ", "dump_trace;", "" ] +[ "sql", "dump_trace", "pattern sql.dump_trace() (X_0:bat[:lng], X_1:bat[:str], X_2:bat[:str]) ", "dump_trace;", "" ] [ "sql", "emptybind", "pattern sql.emptybind(X_0:int, X_1:str, X_2:str, X_3:str, X_4:int) (X_5:bat[:oid], X_6:bat[:any_1]) ", "mvc_bind_wrap;", "" ] [ "sql", "emptybind", "pattern sql.emptybind(X_0:int, X_1:str, X_2:str, X_3:str, X_4:int):bat[:any_1] ", "mvc_bind_wrap;", "" ] [ "sql", "emptybind", "pattern sql.emptybind(X_0:int, X_1:str, X_2:str, X_3:str, X_4:int, X_5:int, X_6:int) (X_7:bat[:oid], X_8:bat[:any_1]) ", "mvc_bind_wrap;", "" ] diff --git a/clients/Tests/MAL-signatures.stable.out.int128 b/clients/Tests/MAL-signatures.stable.out.int128 --- a/clients/Tests/MAL-signatures.stable.out.int128 +++ b/clients/Tests/MAL-signatures.stable.out.int128 @@ -12581,7 +12581,7 @@ stdout of test 'MAL-signatures` in direc [ "sql", "droporderindex", "unsafe pattern sql.droporderindex(X_0:str, X_1:str, X_2:str):void ", "sql_droporderindex;", "" ] [ "sql", "dump_cache", "pattern sql.dump_cache() (X_0:bat[:str], X_1:bat[:int]) ", "dump_cache;", "" ] [ "sql", "dump_opt_stats", "pattern sql.dump_opt_stats() (X_0:bat[:str], X_1:bat[:int]) ", "dump_opt_stats;", "" ] -[ "sql", "dump_trace", "pattern sql.dump_trace() (X_0:bat[:lng], X_1:bat[:str]) ", "dump_trace;", "" ] +[ "sql", "dump_trace", "pattern sql.dump_trace() (X_0:bat[:lng], X_1:bat[:str], X_2:bat[:str]) ", "dump_trace;", "" ] [ "sql", "emptybind", "pattern sql.emptybind(X_0:int, X_1:str, X_2:str, X_3:str, X_4:int) (X_5:bat[:oid], X_6:bat[:any_1]) ", "mvc_bind_wrap;", "" ] [ "sql", "emptybind", "pattern sql.emptybind(X_0:int, X_1:str, X_2:str, X_3:str, X_4:int):bat[:any_1] ", "mvc_bind_wrap;", "" ] [ "sql", "emptybind", "pattern sql.emptybind(X_0:int, X_1:str, X_2:str, X_3:str, X_4:int, X_5:int, X_6:int) (X_7:bat[:oid], X_8:bat[:any_1]) ", "mvc_bind_wrap;", "" ] diff --git a/monetdb5/mal/mal_client.h b/monetdb5/mal/mal_client.h --- a/monetdb5/mal/mal_client.h +++ b/monetdb5/mal/mal_client.h @@ -82,6 +82,7 @@ typedef struct CLIENT { /* The user can request a TRACE SQL statement, calling for collecting the events locally */ BAT *profticks; BAT *profstmt; + BAT *profevents; ATOMIC_TYPE lastprint; /* when we last printed the query, to be depricated */ /* 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 @@ -182,8 +182,8 @@ EXAMPLE: } "stmt":"X_41=0@0:void := querylog.define(\"select count(*) from tables;\":str,\"default_pipe\":str,30:int);", */ -static void -renderProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, int start) +static str +prepareProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, int start) { struct logbuf logbuf; str c; @@ -199,14 +199,14 @@ renderProfilerEvent(Client cntxt, MalBlk if( !start && pci->calls > HIGHWATERMARK){ if( pci->calls == 10000 || pci->calls == 100000 || pci->calls == 1000000 || pci->calls == 10000000) TRC_WARNING(MAL_SERVER, "Too many calls: %d\n", pci->calls); - return; + return NULL; } /* The stream of events can be complete read by the DBA, * all other users can only see events assigned to their account */ if(malprofileruser!= MAL_ADMIN && malprofileruser != cntxt->user) - return; + return NULL; logbuf = (struct logbuf) {0}; @@ -235,16 +235,16 @@ renderProfilerEvent(Client cntxt, MalBlk getModuleId(getInstrPtr(mb, 0)), getFunctionId(getInstrPtr(mb, 0)), mb?getPC(mb,pci):0, stk?stk->tag:0)) - return; + return NULL; if( pci->modname && !logadd(&logbuf, ",\"module\":\"%s\"", pci->modname ? pci->modname : "")) - return; + return NULL; if( pci->fcnname && !logadd(&logbuf, ",\"function\":\"%s\"", pci->fcnname ? pci->fcnname : "")) - return; + return NULL; if( pci->barrier && !logadd(&logbuf, ",\"barrier\":\"%s\"", operatorName(pci->barrier))) - return; + return NULL; if ((pci->token < FCNcall || pci->token > PATcall) && !logadd(&logbuf, ",\"operator\":\"%s\"", operatorName(pci->token))) - return; + return NULL; if (!GDKinmemory(0) && !GDKembedded()) { char *uuid = NULL; str c; @@ -252,16 +252,16 @@ renderProfilerEvent(Client cntxt, MalBlk ok = logadd(&logbuf, ",\"session\":\"%s\"", uuid); free(uuid); if (!ok) - return; + return NULL; } else free(c); } if (!logadd(&logbuf, ",\"state\":\"%s\",\"usec\":"LLFMT, start?"start":"done", pci->ticks)) - return; + return NULL; const char *algo = MT_thread_getalgorithm(); if (algo && !logadd(&logbuf, ",\"algorithm\":\"%s\"", algo)) - return; + return NULL; /* EXAMPLE MAL statement argument decomposition * The eventparser may assume this layout for ease of parsing @@ -279,7 +279,7 @@ renderProfilerEvent(Client cntxt, MalBlk int j; if (!logadd(&logbuf, ",\"args\":[")) - return; + return NULL; for(j=0; j< pci->argc; j++){ int tpe = getVarType(mb, getArg(pci,j)); str tname = 0, cv; @@ -290,16 +290,16 @@ renderProfilerEvent(Client cntxt, MalBlk if (j == 0) { // No comma at the beginning if (!logadd(&logbuf, "{")) - return; + return NULL; } else { if (!logadd(&logbuf, ",{")) - return; + return NULL; } if (!logadd(&logbuf, "\"%s\":%d,\"var\":\"%s\"", j < pci->retc ? "ret" : "arg", j, getVarName(mb, getArg(pci,j)))) - return; + return NULL; c =getVarName(mb, getArg(pci,j)); if(getVarSTC(mb,getArg(pci,j))){ InstrPtr stc = getInstrPtr(mb, getVarSTC(mb,getArg(pci,j))); @@ -310,7 +310,7 @@ renderProfilerEvent(Client cntxt, MalBlk getVarConstant(mb, getArg(stc,stc->retc +1)).val.sval, getVarConstant(mb, getArg(stc,stc->retc +2)).val.sval, getVarConstant(mb, getArg(stc,stc->retc +3)).val.sval)) - return; + return NULL; } if(isaBatType(tpe)){ BAT *d= BATdescriptor(bid = stk->stk[getArg(pci,j)].val.bval); @@ -318,7 +318,7 @@ renderProfilerEvent(Client cntxt, MalBlk ok = logadd(&logbuf, ",\"type\":\"bat[:%s]\"", tname); GDKfree(tname); if (!ok) - return; + return NULL; if(d) { BAT *v; cnt = BATcount(d); @@ -332,10 +332,10 @@ renderProfilerEvent(Client cntxt, MalBlk VIEWtparent(d), d->hseqbase, v && !v->batTransient ? "persistent" : "transient")) - return; + return NULL; } else { if (!logadd(&logbuf, ",\"mode\":\"%s\"", (d->batTransient ? "transient" : "persistent"))) - return; + return NULL; } if (!logadd(&logbuf, ",\"sorted\":%d" @@ -348,7 +348,7 @@ renderProfilerEvent(Client cntxt, MalBlk d->tnonil, d->tnil, d->tkey)) - return; + return NULL; #define keepprop(NME, LNME)\ {const void *valp = BATgetprop(d, NME); \ if ( valp){\ @@ -359,7 +359,7 @@ if ( valp){\ GDKfree(cv);\ GDKfree(cvquote);\ if (!ok)\ - return;\ + return NULL;\ }\ }} keepprop(GDK_MIN_VALUE,"min"); @@ -378,18 +378,18 @@ if ( valp){\ ok = logadd(&logbuf, ",\"file\":\"%s\"", cv + 1); GDKfree(cv); if (!ok) - return; + return NULL; total += cnt * d->twidth; if (!logadd(&logbuf, ",\"width\":%d", d->twidth)) - return; + return NULL; /* keeping information about the individual auxiliary heaps is helpful during analysis. */ if( d->thash && !logadd(&logbuf, ",\"hash\":" LLFMT, (lng) hashinfo(d->thash, d->batCacheid))) - return; + return NULL; if( d->tvheap && !logadd(&logbuf, ",\"vheap\":" LLFMT, (lng) heapinfo(d->tvheap, d->batCacheid))) - return; + return NULL; if( d->timprints && !logadd(&logbuf, ",\"imprints\":" LLFMT, (lng) IMPSimprintsize(d))) - return; - /* if (!logadd(&logbuf, "\"debug\":\"%s\",", d->debugmessages)) return; */ + return NULL; + /* if (!logadd(&logbuf, "\"debug\":\"%s\",", d->debugmessages)) return NULL; */ BBPunfix(d->batCacheid); } if (!logadd(&logbuf, @@ -397,7 +397,7 @@ if ( valp){\ ",\"count\":"BUNFMT ",\"size\":" LLFMT, bid, cnt, total)) - return; + return NULL; } else{ tname = getTypeName(tpe); ok = logadd(&logbuf, @@ -406,7 +406,7 @@ if ( valp){\ tname, isVarConstant(mb, getArg(pci,j))); GDKfree(tname); if (!ok) - return; + return NULL; cv = VALformat(&stk->stk[getArg(pci,j)]); stmtq = cv ? mal_quote(cv, strlen(cv)) : NULL; if (stmtq) @@ -414,21 +414,31 @@ if ( valp){\ GDKfree(cv); GDKfree(stmtq); if (!ok) - return; + return NULL; } if (!logadd(&logbuf, ",\"eol\":%d", getVarEolife(mb,getArg(pci,j)))) - return; - // if (!logadd(&logbuf, ",\"fixed\":%d", isVarFixed(mb,getArg(pci,j)))) return; + return NULL; + // if (!logadd(&logbuf, ",\"fixed\":%d", isVarFixed(mb,getArg(pci,j)))) return NULL; if (!logadd(&logbuf, "}")) - return; + return NULL; } if (!logadd(&logbuf, "]")) // end marker for arguments - return; + return NULL; } if (!logadd(&logbuf, "}\n")) // end marker - return; - logjsonInternal(logbuf.logbuffer); - logdel(&logbuf); + return NULL; + return logbuf.logbuffer; +} + +static void +renderProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, int start) +{ + str ev; + ev = prepareProfilerEvent(cntxt, mb, stk, pci, start); + if( ev ){ + logjsonInternal(ev); + GDKfree(ev); + } } /* the OS details on cpu load are read from /proc/stat @@ -711,7 +721,9 @@ static void BBPunfix(cntxt->profticks->batCacheid); if (cntxt->profstmt) BBPunfix(cntxt->profstmt->batCacheid); - cntxt->profticks = cntxt->profstmt = NULL; + if (cntxt->profevents) + BBPunfix(cntxt->profevents->batCacheid); + cntxt->profticks = cntxt->profstmt = cntxt->profevents = NULL; } static BAT * @@ -735,7 +747,8 @@ initTrace(Client cntxt) } cntxt->profticks = TRACEcreate(TYPE_lng); cntxt->profstmt = TRACEcreate(TYPE_str); - if (cntxt->profticks == NULL || cntxt->profstmt == NULL) + cntxt->profevents = TRACEcreate(TYPE_str); + if (cntxt->profticks == NULL || cntxt->profstmt == NULL || cntxt->profevents == NULL) _cleanupProfiler(cntxt); MT_lock_unset(&mal_profileLock); } @@ -751,8 +764,9 @@ TRACEtable(Client cntxt, BAT **r) } r[0] = COLcopy(cntxt->profticks, cntxt->profticks->ttype, false, TRANSIENT); r[1] = COLcopy(cntxt->profstmt, cntxt->profstmt->ttype, false, TRANSIENT); + r[2] = COLcopy(cntxt->profevents, cntxt->profevents->ttype, false, TRANSIENT); MT_lock_unset(&mal_profileLock); - return 2; + return 3; } _______________________________________________ checkin-list mailing list checkin-list@monetdb.org https://www.monetdb.org/mailman/listinfo/checkin-list