Changeset: 7ba8ed6d4865 for MonetDB
URL: https://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=7ba8ed6d4865
Modified Files:
monetdb5/mal/mal_profiler.c
Branch: Jul2017
Log Message:
Add support for long SQL texts in the profiler
This is related to Bug 6375, but is still incomplete.
The problem is that the profiler truncates JSON objects to 8KB. There are two
solutions to this problem:
1. Since the location of the very big parts of the MAL plan are
known (statement text, short statement text, and value in argument list) we
can truncate only these parts, and thus produce a complete JSON object. The
problem with this approach is that we do not know in advance how much we need
to truncate, because other elements are to follow and everything needs to fit
in 8KB.
2. Transmit more than 8KB chunks. The obvious downside to this is that we will
need more IO and since the query itself can in principle be unbounded, this
can be very expensive.
The solution is the combination of the above. We truncate the big parts and so
effectively we make the amount of IO bounded but also recognizing that they
contain useful information, and try to minimize the information loss.
Still TODO:
The concatenation and transmission of big objects is buggy. The problem can be
reproduced with the command:
python -c "print(\"select * from _tables where name='\" + 'a'*8192 + \"';\")" |
mclient -d
diffs (147 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
@@ -26,6 +26,8 @@
#include <sys/time.h>
#endif
+#include <string.h>
+
static void cachedProfilerEvent(MalBlkPtr mb, MalStkPtr stk, InstrPtr pci);
stream *eventstream = 0;
@@ -62,16 +64,23 @@ static struct{
#define LOGLEN 8192
#define lognew() loglen = 0; logbase = logbuffer; *logbase = 0;
-#define logadd(...) {
\
+#define logadd(...)
\
do {
\
- if (loglen < LOGLEN)
\
+ char tmp_buff[LOGLEN];
\
+ int tmp_len = 0;
\
+ tmp_len = snprintf(tmp_buff, LOGLEN, __VA_ARGS__);
\
+ if (loglen + tmp_len < LOGLEN)
\
loglen += snprintf(logbase+loglen, LOGLEN - loglen,
__VA_ARGS__); \
- } while (0);}
-
+ else {
\
+ logjsonInternal(logbuffer);
\
+ lognew();
\
+ loglen += snprintf(logbase+loglen, LOGLEN - loglen,
__VA_ARGS__); \
+ }
\
+ } while (0)
// The heart beat events should be sent to all outstanding channels.
static void logjsonInternal(char *logbuffer)
-{
+{
size_t len;
len = strlen(logbuffer);
@@ -85,6 +94,28 @@ static void logjsonInternal(char *logbuf
MT_lock_unset(&mal_profileLock);
}
+static char *
+truncate_string(char *inp)
+{
+ size_t len;
+ char *ret;
+ size_t ret_len = LOGLEN/2;
+ size_t padding = 64;
+
+ len = strlen(inp);
+ ret = (char *)GDKmalloc(ret_len + 1);
+ if (ret == NULL) {
+ return NULL;
+ }
+
+ *ret = 0;
+ ret = strncat(ret, inp, ret_len/2);
+ ret = strncat(ret, " ...<truncated>... ", strlen(" ...<truncated>...
"));
+ ret = strncat(ret, inp + (len - ret_len/2 + padding), ret_len/2 -
padding);
+
+ return ret;
+}
+
/* JSON rendering method of performance data.
* The eventparser may assume this layout for ease of parsing
EXAMPLE:
@@ -109,7 +140,7 @@ static void
renderProfilerEvent(MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, int start, str
usrname)
{
char logbuffer[LOGLEN], *logbase;
- int loglen;
+ size_t loglen;
str stmt, c;
str stmtq;
lng usec= GDKusec();
@@ -129,7 +160,8 @@ renderProfilerEvent(MalBlkPtr mb, MalStk
logadd("{%s",prettify); // fill in later with the event counter
if( usrname)
- logadd("\"user\":\"%s\",%s",usrname, prettify);
+ //logadd("\"user\":\"%s\",%s",usrname, prettify);
+
logadd("\"clk\":"LLFMT",%s",usec,prettify);
logadd("\"ctime\":"LLFMT".%06ld,%s", sec, microseconds, prettify);
logadd("\"thread\":%d,%s", THRgettid(),prettify);
@@ -184,6 +216,7 @@ renderProfilerEvent(MalBlkPtr mb, MalStk
size_t len;
int i,j,k,comma;
InstrPtr q;
+ char *truncated;
/* generate actual call statement */
stmt = instruction2str(mb, stk, pci, LIST_MAL_ALL);
@@ -194,8 +227,13 @@ renderProfilerEvent(MalBlkPtr mb, MalStk
c++;
if( *c){
stmtq = mal_quote(c, strlen(c));
+ if (stmtq && strlen(stmtq) > LOGLEN/2) {
+ truncated = truncate_string(stmtq);
+ GDKfree(stmtq);
+ stmtq = truncated;
+ }
if (stmtq != NULL) {
- logadd("\"stmt\":\"%s\",%s",
stmtq,prettify);
+ logadd("\"stmt\":\"%s\",%s", stmtq,
prettify);
GDKfree(stmtq);
}
}
@@ -206,10 +244,15 @@ renderProfilerEvent(MalBlkPtr mb, MalStk
stmt = shortStmtRendering(mb, stk, pci);
stmtq = mal_quote(stmt, strlen(stmt));
+ if (stmtq && strlen(stmtq) > LOGLEN/2) {
+ truncated = truncate_string(stmtq);
+ GDKfree(stmtq);
+ stmtq = truncated;
+ }
if (stmtq != NULL) {
logadd("\"short\":\"%s\",%s", stmtq, prettify);
GDKfree(stmtq);
- }
+ }
GDKfree(stmt);
@@ -302,11 +345,17 @@ This information can be used to determin
logadd("\"count\":\""BUNFMT"\",%s",cnt,pret);
logadd("\"size\":" LLFMT",%s",
total,pret);
} else{
+ char *truncated;
tname = getTypeName(tpe);
logadd("\"type\":\"%s\",%s",
tname,pret);
cv = 0;
VALformat(&cv,
&stk->stk[getArg(pci,j)]);
stmtq = mal_quote(cv, strlen(cv));
+ if (stmtq != NULL && strlen(stmtq) >
LOGLEN/2) {
+ truncated =
truncate_string(stmtq);
+ GDKfree(stmtq);
+ stmtq = truncated;
+ }
logadd("\"value\":\"%s\",%s",
stmtq,pret);
GDKfree(cv);
GDKfree(stmtq);
_______________________________________________
checkin-list mailing list
[email protected]
https://www.monetdb.org/mailman/listinfo/checkin-list
