Changeset: f1bda60713b5 for MonetDB
URL: https://dev.monetdb.org/hg/MonetDB/rev/f1bda60713b5
Modified Files:
clients/Tests/MAL-signatures-hge.test
clients/Tests/MAL-signatures.test
clients/Tests/exports.stable.out
Branch: Sep2022
Log Message:
Merge with sql_profiler.
diffs (truncated from 1470 to 300 lines):
diff --git a/clients/Tests/MAL-signatures-hge.test
b/clients/Tests/MAL-signatures-hge.test
--- a/clients/Tests/MAL-signatures-hge.test
+++ b/clients/Tests/MAL-signatures-hge.test
@@ -47779,6 +47779,11 @@ pattern profiler.openstream():void
CMDopenProfilerStream;
Start profiling the events, send to output stream
profiler
+openstream
+pattern profiler.openstream(X_0:str):void
+CMDopenProfilerStream;
+Start profiling the events, send to output stream
+profiler
setheartbeat
unsafe command profiler.setheartbeat(X_0:int):void
CMDsetHeartbeat;
diff --git a/clients/Tests/MAL-signatures.test
b/clients/Tests/MAL-signatures.test
--- a/clients/Tests/MAL-signatures.test
+++ b/clients/Tests/MAL-signatures.test
@@ -36204,6 +36204,11 @@ pattern profiler.openstream():void
CMDopenProfilerStream;
Start profiling the events, send to output stream
profiler
+openstream
+pattern profiler.openstream(X_0:str):void
+CMDopenProfilerStream;
+Start profiling the events, send to output stream
+profiler
setheartbeat
unsafe command profiler.setheartbeat(X_0:int):void
CMDsetHeartbeat;
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
@@ -1111,7 +1111,6 @@ str malIncludeModules(Client c, char *mo
str malIncludeString(Client c, const char *name, str mal, int listing, MALfcn
address);
int malLibraryEnabled(const char *name);
char *malLibraryHowToEnable(const char *name);
-int malProfileMode;
const char *malRef;
void mal_atom_reset(void);
ClientRec *mal_clients;
@@ -1211,7 +1210,7 @@ const char *not_uniqueRef;
const char *nth_valueRef;
const char *ntileRef;
const char *oidRef;
-str openProfilerStream(Client cntxt);
+str openProfilerStream(Client cntxt, str s);
const char *openRef;
str operatorName(int i);
void opt_pipes_reset(void);
@@ -1240,10 +1239,12 @@ const char *printRef;
void printSignature(stream *fd, Symbol s, int flg);
void printStack(stream *f, MalBlkPtr mb, MalStkPtr s);
const char *prodRef;
-void profilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci,
int start);
+void profilerEvent(MalEvent me, NonMalEvent nme);
void profilerGetCPUStat(lng *user, lng *nice, lng *sys, lng *idle, lng
*iowait);
void profilerHeartbeatEvent(char *alter);
+int profilerMode;
const char *profilerRef;
+int profilerStatus;
const char *projectRef;
const char *projectdeltaRef;
const char *projectionRef;
@@ -1325,6 +1326,7 @@ void runtimeProfileBegin(Client cntxt, M
void runtimeProfileExit(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr
pci, RuntimeProfile prof);
void runtimeProfileFinish(Client cntxt, MalBlkPtr mb, MalStkPtr stk);
void runtimeProfileInit(Client cntxt, MalBlkPtr mb, MalStkPtr stk);
+oid runtimeProfileSetTag(Client cntxt);
const char *sampleRef;
const char *schedulerRef;
const char *selectNotNilRef;
diff --git a/monetdb5/mal/mal.h b/monetdb5/mal/mal.h
--- a/monetdb5/mal/mal.h
+++ b/monetdb5/mal/mal.h
@@ -158,7 +158,6 @@ typedef struct {
/* inline statistics */
lng clock; /* when the last call
was started */
lng ticks; /* total micro seconds
spent in last call */
- int calls; /* number of calls made
to this instruction */
lng totticks; /* total time spent on this
instruction. */
lng wbytes; /* number of bytes
produced in last instruction */
/* the core admin */
diff --git a/monetdb5/mal/mal_client.c b/monetdb5/mal/mal_client.c
--- a/monetdb5/mal/mal_client.c
+++ b/monetdb5/mal/mal_client.c
@@ -183,7 +183,9 @@ MCresetProfiler(stream *fdout)
if (fdout != maleventstream)
return;
MT_lock_set(&mal_profileLock);
- maleventstream = 0;
+ maleventstream = NULL;
+ profilerStatus = 0;
+ profilerMode = 0;
MT_lock_unset(&mal_profileLock);
}
@@ -207,6 +209,13 @@ MCexitClient(Client c)
c->fdout = NULL;
c->fdin = NULL;
}
+ assert(c->query == NULL);
+ if(profilerStatus > 0) {
+ lng Tend = GDKusec();
+ profilerEvent((struct MalEvent) {0},
+ (struct NonMalEvent)
+ {CLIENT_END, c, Tend, NULL, NULL, 0,
Tend-(c->session)});
+ }
setClientContext(NULL);
}
@@ -292,7 +301,6 @@ MCinitClient(oid user, bstream *fin, str
MT_lock_set(&mal_contextLock);
c = MCnewClient();
-
if (c) {
Client c_old = setClientContext(c);
(void) c_old;
@@ -300,6 +308,10 @@ MCinitClient(oid user, bstream *fin, str
c = MCinitClientRecord(c, user, fin, fout);
}
MT_lock_unset(&mal_contextLock);
+
+ profilerEvent((struct MalEvent) {0},
+ (struct NonMalEvent)
+ {CLIENT_START, c, c->session, NULL, NULL, 0,
0});
return c;
}
diff --git a/monetdb5/mal/mal_dataflow.c b/monetdb5/mal/mal_dataflow.c
--- a/monetdb5/mal/mal_dataflow.c
+++ b/monetdb5/mal/mal_dataflow.c
@@ -447,7 +447,7 @@ DFLOWworker(void *T)
#endif
q_enqueue(flow->done, fe);
- if ( fnxt == 0 && malProfileMode) {
+ if ( fnxt == 0 && profilerStatus) {
profilerHeartbeatEvent("wait");
}
}
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,10 +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.
- * 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
+ * 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.
*/
#include "monetdb_config.h"
@@ -39,15 +40,9 @@ static const char *myname = 0; // avoid
* also the term rendering to be set to ''
*/
-/* When the MAL block contains a BARRIER block we may end up with tons
- * of profiler events. To avoid this, we stop emitting the events
- * when we reached the HIGHWATERMARK. Leaving a message in the log.
- */
-#define HIGHWATERMARK 5
-
-
-int malProfileMode = 0; /* global flag to indicate profiling mode */
-static oid malprofileruser; /* keep track on who has claimed the channel */
+int profilerStatus = 0; /* global flag profiler status */
+int profilerMode = 0; /* global flag profiler mode, minimal or detailed
*/
+static oid profilerUser; /* keep track on who has claimed the channel */
static struct timeval startup_time;
@@ -60,14 +55,12 @@ static struct rusage prevUsage;
#define LOGLEN 8192
-// The heart beat events should be sent to all outstanding channels.
static void logjsonInternal(char *logbuffer, bool flush)
{
size_t len;
len = strlen(logbuffer);
if (maleventstream) {
- // upon request the log record is sent over the profile stream
(void) mnstr_write(maleventstream, logbuffer, 1, len);
if (flush)
(void) mnstr_flush(maleventstream, MNSTR_FLUSH_DATA);
@@ -75,24 +68,29 @@ static void logjsonInternal(char *logbuf
}
/*
- * We use a buffer (`logbuffer`) where we incrementally create the output JSON
object. Initially we allocate LOGLEN (8K)
- * bytes and we keep the capacity of the buffer (`logcap`) and the length of
the current string (`loglen`).
+ * We use a buffer (`logbuffer`) where we incrementally create the output JSON
+ * object. Initially we allocate LOGLEN (8K)
+ * bytes and we keep the capacity of the buffer (`logcap`) and the length of
the
+ * current string (`loglen`).
*
- * We use the `logadd` function to add data to our buffer (usually key-value
pairs). This macro offers an interface similar
- * to printf.
+ * We use the `logadd` function to add data to our buffer (usually key-value
+ * pairs). This macro offers an interface similar to printf.
*
- * The first snprintf below happens in a statically allocated buffer that
might be much smaller than logcap. We do not
- * care. We only need to perform this snprintf to get the actual length of the
string that is to be produced.
+ * The first snprintf below happens in a statically allocated buffer that might
+ * be much smaller than logcap. We do not care. We only need to perform this
+ * snprintf to get the actual length of the string that is to be produced.
*
* There are three cases:
*
* 1. The new string fits in the current buffer -> we just update the buffer
*
- * 2. The new string does not fit in the current buffer, but is smaller than
the capacity of the buffer -> we output the
- * current contents of the buffer and start at the beginning.
+ * 2. The new string does not fit in the current buffer, but is smaller than
the
+ * capacity of the buffer -> we output the current contents of the buffer and
+ * start at the beginning.
*
- * 3. The new string exceeds the current capacity of the buffer -> we output
the current contents and reallocate the
- * buffer. The new capacity is 1.5 times the length of the new string.
+ * 3. The new string exceeds the current capacity of the buffer -> we output
the
+ * current contents and reallocate the buffer. The new capacity is 1.5 times
the
+ * length of the new string.
*/
struct logbuf {
char *logbuffer;
@@ -169,55 +167,133 @@ logadd(struct logbuf *logbuf, const char
return true;
}
-/* JSON rendering method of performance data.
- * The eventparser may assume this layout for ease of parsing
- EXAMPLE:
- {
- "event":6 ,
- "thread":3,
- "function":"user.s3_1",
- "pc":1,
- "tag":10397,
- "state":"start",
- "usec":0,
- }
- "stmt":"X_41=0@0:void := querylog.define(\"select count(*) from
tables;\":str,\"default_pipe\":str,30:int);",
-*/
+static str phase_descriptions[] = {
+ [CLIENT_START] = "session_start",
+ [CLIENT_END] = "session_end",
+ [TEXT_TO_SQL] = "text_to_sql",
+ [SQL_TO_REL] = "sql_to_rel",
+ [REL_OPT] = "rel_opt",
+ [REL_TO_MAL] = "rel_to_mal",
+ [MAL_OPT] = "mal_opt",
+ [MAL_ENGINE] = "mal_engine",
+ [COMMIT] = "trans_commit",
+ [ROLLBACK] = "trans_rollback",
+ [CONFLICT] = "trans_conflict"
+};
+
static str
-prepareProfilerEvent(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci,
int start)
+prepareNonMalEvent(Client cntxt, enum event_phase phase, ulng clk, ulng
*tstart, ulng *tend, int state, ulng duration)
+{
+ oid* tag = NULL;
+ 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);
+
+ 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)) ) == NULL)
+ return NULL;
+
+ 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_descriptions[phase]))
+ goto cleanup_and_exit;
+ if (tstart && !logadd(&logbuf, ", \"tstart\":"ULLFMT, *tstart))
+ goto cleanup_and_exit;
+ if (tend && !logadd(&logbuf, ", \"tend\":"ULLFMT, *tend))
+ goto cleanup_and_exit;
+ if (tag && !logadd(&logbuf, ", \"tag\":"OIDFMT, *tag))
+ goto cleanup_and_exit;
+ if (query && phase == TEXT_TO_SQL && !logadd(&logbuf, ",
\"query\":\"%s\"", query))
+ goto cleanup_and_exit;
_______________________________________________
checkin-list mailing list -- [email protected]
To unsubscribe send an email to [email protected]
