Line data Source code
1 : /*
2 : * SPDX-License-Identifier: MPL-2.0
3 : *
4 : * This Source Code Form is subject to the terms of the Mozilla Public
5 : * License, v. 2.0. If a copy of the MPL was not distributed with this
6 : * file, You can obtain one at http://mozilla.org/MPL/2.0/.
7 : *
8 : * Copyright 2024 MonetDB Foundation;
9 : * Copyright August 2008 - 2023 MonetDB B.V.;
10 : * Copyright 1997 - July 2008 CWI.
11 : */
12 :
13 : /*
14 : * Martin Kersten
15 : * Language Extensions
16 : * Iterators over scalar ranges are often needed, also at the MAL level.
17 : * The barrier and control primitives are sufficient to mimic them directly.
18 : *
19 : * The modules located in the kernel directory should not
20 : * rely on the MAL datastructures. That's why we have to deal with
21 : * some bat operations here and delegate the signature to the
22 : * proper module upon loading.
23 : *
24 : * Running a script is typically used to initialize a context.
25 : * Therefore we need access to the runtime context.
26 : * For the call variants we have
27 : * to determine an easy way to exchange the parameter/return values.
28 : */
29 :
30 : #include "monetdb_config.h"
31 : #include "querylog.h"
32 : #include "gdk_time.h"
33 : #include "mal_exception.h"
34 :
35 : /* (c) M.L. Kersten
36 : * The query logger facility is hardwired to avoid interference
37 : * with the SQL transaction manager.
38 : *
39 : * The events being captured are stored in separate BATs.
40 : * They are made persistent to accumulate information over
41 : * multiple sessions. This means it has to be explicitly reset
42 : * to avoid disc overflow using querylog.reset().
43 : create table querylog.catalog(
44 : id oid,
45 : "user" string, -- owner of the query
46 : defined timestamp, -- when entered into the cache
47 : query string,
48 : pipe string, -- optimizer pipe-line deployed
49 : optimize bigint -- time in usec
50 : );
51 : create table querylog.calls(
52 : id oid,
53 : "start" timestamp, -- time the statement was started
54 : "stop" timestamp, -- time the statement was completely finished
55 : arguments string,
56 : tuples lng, -- number of tuples in the result set
57 : exec bigint, -- time spent (in usec) until the result export
58 : result bigint, -- time spent (in usec) to ship the result set
59 : cpuload int, -- average cpu load percentage during execution
60 : iowait int -- time waiting for IO to finish in usec
61 : );
62 : */
63 :
64 : static bool QLOGtrace = false;
65 : static bool QLOG_init = false;
66 : static lng QLOGthreshold = 0;
67 :
68 : static BAT *QLOG_cat_id = 0;
69 : static BAT *QLOG_cat_user = 0;
70 : static BAT *QLOG_cat_defined = 0;
71 : static BAT *QLOG_cat_query = 0;
72 : static BAT *QLOG_cat_pipe = 0;
73 : static BAT *QLOG_cat_plan = 0;
74 : static BAT *QLOG_cat_mal = 0;
75 : static BAT *QLOG_cat_optimize = 0;
76 :
77 : static BAT *QLOG_calls_id = 0;
78 : static BAT *QLOG_calls_start = 0;
79 : static BAT *QLOG_calls_stop = 0;
80 : static BAT *QLOG_calls_arguments = 0;
81 : static BAT *QLOG_calls_tuples = 0;
82 : static BAT *QLOG_calls_exec = 0;
83 : static BAT *QLOG_calls_result = 0;
84 : static BAT *QLOG_calls_cpuload = 0;
85 : static BAT *QLOG_calls_iowait = 0;
86 :
87 : static MT_Lock QLOGlock = MT_LOCK_INITIALIZER(QLOGlock);
88 :
89 : static str initQlog(void);
90 :
91 : str
92 107 : QLOGcatalog(BAT **r)
93 : {
94 107 : int i, cnt = 0;
95 107 : str msg;
96 :
97 963 : for (i = 0; i < 8; i++)
98 856 : r[i] = 0;
99 107 : msg = initQlog();
100 107 : if (msg)
101 : return msg;
102 107 : MT_lock_set(&QLOGlock);
103 107 : r[0] = COLcopy(QLOG_cat_id, QLOG_cat_id->ttype, false, TRANSIENT);
104 107 : r[1] = COLcopy(QLOG_cat_user, QLOG_cat_user->ttype, false, TRANSIENT);
105 107 : r[2] = COLcopy(QLOG_cat_defined, QLOG_cat_defined->ttype, false, TRANSIENT);
106 107 : r[3] = COLcopy(QLOG_cat_query, QLOG_cat_query->ttype, false, TRANSIENT);
107 107 : r[4] = COLcopy(QLOG_cat_pipe, QLOG_cat_pipe->ttype, false, TRANSIENT);
108 107 : r[5] = COLcopy(QLOG_cat_plan, QLOG_cat_plan->ttype, false, TRANSIENT);
109 107 : r[6] = COLcopy(QLOG_cat_mal, QLOG_cat_mal->ttype, false, TRANSIENT);
110 107 : r[7] = COLcopy(QLOG_cat_optimize, QLOG_cat_optimize->ttype, false,
111 : TRANSIENT);
112 107 : MT_lock_unset(&QLOGlock);
113 1070 : for (i = 0; i < 8; i++)
114 856 : cnt += r[i] != 0;
115 107 : if (cnt != 8) {
116 0 : for (i = 0; i < 8; i++)
117 0 : if (r[i]) {
118 0 : BBPunfix(r[i]->batCacheid);
119 0 : r[i] = 0;
120 : }
121 : }
122 107 : if (r[0])
123 : return MAL_SUCCEED;
124 0 : throw(MAL, "catalog_queries", SQLSTATE(HY013) MAL_MALLOC_FAIL);
125 : }
126 :
127 : str
128 79 : QLOGcalls(BAT **r)
129 : {
130 79 : int i, cnt = 0;
131 79 : str msg;
132 :
133 869 : for (i = 0; i < 10; i++)
134 790 : r[i] = 0;
135 79 : msg = initQlog();
136 79 : if (msg)
137 : return msg;
138 79 : MT_lock_set(&QLOGlock);
139 79 : r[0] = COLcopy(QLOG_calls_id, QLOG_calls_id->ttype, false, TRANSIENT);
140 79 : r[1] = COLcopy(QLOG_calls_start, QLOG_calls_start->ttype, false, TRANSIENT);
141 79 : r[2] = COLcopy(QLOG_calls_stop, QLOG_calls_stop->ttype, false, TRANSIENT);
142 79 : r[3] = COLcopy(QLOG_calls_arguments, QLOG_calls_arguments->ttype, false,
143 : TRANSIENT);
144 79 : r[4] = COLcopy(QLOG_calls_tuples, QLOG_calls_tuples->ttype, false,
145 : TRANSIENT);
146 79 : r[5] = COLcopy(QLOG_calls_exec, QLOG_calls_exec->ttype, false, TRANSIENT);
147 79 : r[6] = COLcopy(QLOG_calls_result, QLOG_calls_result->ttype, false,
148 : TRANSIENT);
149 79 : r[7] = COLcopy(QLOG_calls_cpuload, QLOG_calls_cpuload->ttype, false,
150 : TRANSIENT);
151 79 : r[8] = COLcopy(QLOG_calls_iowait, QLOG_calls_iowait->ttype, false,
152 : TRANSIENT);
153 79 : MT_lock_unset(&QLOGlock);
154 869 : for (i = 0; i < 9; i++)
155 711 : cnt += r[i] != 0;
156 79 : if (cnt != 9) {
157 0 : for (i = 0; i < 9; i++)
158 0 : if (r[i]) {
159 0 : BBPunfix(r[i]->batCacheid);
160 0 : r[i] = 0;
161 : }
162 : }
163 79 : if (r[0])
164 : return MAL_SUCCEED;
165 0 : throw(MAL, "catalog_calls", SQLSTATE(HY013) MAL_MALLOC_FAIL);
166 : }
167 :
168 : #define MAXCOMMITLIST 32
169 : static bat commitlist[MAXCOMMITLIST];
170 : static int committop = 1;
171 :
172 : static BAT *
173 238 : QLOGcreate(const char *hnme, const char *tnme, int tt)
174 : {
175 238 : BAT *b;
176 238 : char buf[128];
177 :
178 238 : snprintf(buf, 128, "querylog_%s_%s", hnme, tnme);
179 238 : b = BATdescriptor(BBPindex(buf));
180 238 : if (b) {
181 : /* make append-only in case this wasn't done when created */
182 0 : return BATsetaccess(b, BAT_APPEND);
183 : }
184 :
185 238 : b = COLnew(0, tt, 1 << 16, PERSISTENT);
186 238 : if (b == NULL)
187 : return NULL;
188 238 : if ((b = BATsetaccess(b, BAT_APPEND)) == NULL)
189 : return NULL;
190 :
191 238 : if (BBPrename(b, buf) != 0 || BATmode(b, false) != GDK_SUCCEED) {
192 0 : BBPunfix(b->batCacheid);
193 0 : return NULL;
194 : }
195 238 : commitlist[committop++] = b->batCacheid;
196 238 : assert(committop < MAXCOMMITLIST);
197 : return b;
198 : }
199 :
200 : #define cleanup(X) \
201 : do { \
202 : if (X) { \
203 : (X)->batTransient = true; \
204 : BBPrename((X), NULL); \
205 : BBPunfix((X)->batCacheid); \
206 : } \
207 : (X) = NULL; \
208 : } while (0)
209 :
210 : static void
211 0 : _QLOGcleanup(void)
212 : {
213 0 : cleanup(QLOG_cat_id);
214 0 : cleanup(QLOG_cat_user);
215 0 : cleanup(QLOG_cat_defined);
216 0 : cleanup(QLOG_cat_query);
217 0 : cleanup(QLOG_cat_pipe);
218 0 : cleanup(QLOG_cat_plan);
219 0 : cleanup(QLOG_cat_mal);
220 0 : cleanup(QLOG_cat_optimize);
221 :
222 0 : cleanup(QLOG_calls_id);
223 0 : cleanup(QLOG_calls_start);
224 0 : cleanup(QLOG_calls_stop);
225 0 : cleanup(QLOG_calls_arguments);
226 0 : cleanup(QLOG_calls_tuples);
227 0 : cleanup(QLOG_calls_exec);
228 0 : cleanup(QLOG_calls_result);
229 0 : cleanup(QLOG_calls_cpuload);
230 0 : cleanup(QLOG_calls_iowait);
231 0 : }
232 :
233 : static str
234 14 : _initQlog(void)
235 : {
236 14 : QLOG_cat_id = QLOGcreate("cat", "id", TYPE_oid);
237 14 : QLOG_cat_user = QLOGcreate("cat", "user", TYPE_str);
238 14 : QLOG_cat_defined = QLOGcreate("cat", "defined", TYPE_timestamp);
239 14 : QLOG_cat_query = QLOGcreate("cat", "query", TYPE_str);
240 14 : QLOG_cat_pipe = QLOGcreate("cat", "pipe", TYPE_str);
241 14 : QLOG_cat_plan = QLOGcreate("cat", "size", TYPE_str);
242 14 : QLOG_cat_mal = QLOGcreate("cat", "mal", TYPE_int);
243 14 : QLOG_cat_optimize = QLOGcreate("cat", "optimize", TYPE_lng);
244 :
245 14 : QLOG_calls_id = QLOGcreate("calls", "id", TYPE_oid);
246 14 : QLOG_calls_start = QLOGcreate("calls", "start", TYPE_timestamp);
247 14 : QLOG_calls_stop = QLOGcreate("calls", "stop", TYPE_timestamp);
248 14 : QLOG_calls_arguments = QLOGcreate("calls", "arguments", TYPE_str);
249 14 : QLOG_calls_tuples = QLOGcreate("calls", "tuples", TYPE_lng);
250 14 : QLOG_calls_exec = QLOGcreate("calls", "exec", TYPE_lng);
251 14 : QLOG_calls_result = QLOGcreate("calls", "result", TYPE_lng);
252 14 : QLOG_calls_cpuload = QLOGcreate("calls", "cpuload", TYPE_int);
253 14 : QLOG_calls_iowait = QLOGcreate("calls", "iowait", TYPE_int);
254 :
255 14 : if (QLOG_cat_id == NULL || QLOG_cat_user == NULL || QLOG_cat_defined == NULL
256 14 : || QLOG_cat_query == NULL || QLOG_cat_pipe == NULL
257 14 : || QLOG_cat_plan == NULL || QLOG_cat_mal == NULL
258 14 : || QLOG_cat_optimize == NULL || QLOG_calls_id == NULL
259 14 : || QLOG_calls_start == NULL || QLOG_calls_stop == NULL
260 14 : || QLOG_calls_arguments == NULL || QLOG_calls_tuples == NULL
261 14 : || QLOG_calls_exec == NULL || QLOG_calls_result == NULL
262 14 : || QLOG_calls_cpuload == NULL || QLOG_calls_iowait == NULL) {
263 0 : _QLOGcleanup();
264 0 : throw(MAL, "querylog.init", SQLSTATE(HY013) MAL_MALLOC_FAIL);
265 : }
266 :
267 14 : QLOG_init = true;
268 14 : if (TMsubcommit_list(commitlist, NULL, committop, -1) != GDK_SUCCEED)
269 0 : throw(MAL, "querylog.init", GDK_EXCEPTION);
270 : return MAL_SUCCEED;
271 : }
272 :
273 : static str
274 197 : initQlog(void)
275 : {
276 197 : str msg;
277 :
278 197 : if (QLOG_init)
279 : return MAL_SUCCEED; /* already initialized */
280 14 : MT_lock_set(&QLOGlock);
281 14 : msg = _initQlog();
282 14 : MT_lock_unset(&QLOGlock);
283 14 : return msg;
284 : }
285 :
286 : str
287 1 : QLOGenable(void *ret)
288 : {
289 1 : (void) ret;
290 1 : QLOGtrace = true;
291 1 : QLOGthreshold = 0;
292 1 : return MAL_SUCCEED;
293 : }
294 :
295 : str
296 0 : QLOGenableThreshold(void *ret, const int *threshold)
297 : {
298 0 : (void) ret;
299 0 : QLOGtrace = true;
300 0 : QLOGthreshold = *threshold * LL_CONSTANT(1000);
301 0 : return MAL_SUCCEED;
302 : }
303 :
304 : str
305 1 : QLOGdisable(void *ret)
306 : {
307 1 : (void) ret;
308 1 : QLOGtrace = false;
309 1 : return MAL_SUCCEED;
310 : }
311 :
312 : int
313 483511 : QLOGisset(void)
314 : {
315 483511 : return QLOGtrace;
316 : }
317 :
318 : static str
319 0 : QLOGissetFcn(int *ret)
320 : {
321 0 : *ret = QLOGtrace;
322 0 : return MAL_SUCCEED;
323 : }
324 :
325 : str
326 1 : QLOGempty(void *ret)
327 : {
328 1 : str msg;
329 :
330 1 : (void) ret;
331 1 : msg = initQlog();
332 1 : if (msg)
333 : return msg;
334 1 : MT_lock_set(&QLOGlock);
335 : /* drop all querylog tables */
336 :
337 1 : BATclear(QLOG_cat_id, true);
338 1 : BATclear(QLOG_cat_user, true);
339 1 : BATclear(QLOG_cat_defined, true);
340 1 : BATclear(QLOG_cat_query, true);
341 1 : BATclear(QLOG_cat_pipe, true);
342 1 : BATclear(QLOG_cat_plan, true);
343 1 : BATclear(QLOG_cat_mal, true);
344 1 : BATclear(QLOG_cat_optimize, true);
345 :
346 1 : BATclear(QLOG_calls_id, true);
347 1 : BATclear(QLOG_calls_start, true);
348 1 : BATclear(QLOG_calls_stop, true);
349 1 : BATclear(QLOG_calls_arguments, true);
350 1 : BATclear(QLOG_calls_tuples, true);
351 1 : BATclear(QLOG_calls_exec, true);
352 1 : BATclear(QLOG_calls_result, true);
353 1 : BATclear(QLOG_calls_cpuload, true);
354 1 : BATclear(QLOG_calls_iowait, true);
355 :
356 1 : if (TMsubcommit_list(commitlist, NULL, committop, -1) != GDK_SUCCEED)
357 0 : msg = createException(MAL, "querylog.empty", GDK_EXCEPTION);
358 1 : MT_lock_unset(&QLOGlock);
359 1 : return MAL_SUCCEED;
360 : }
361 :
362 : static str
363 5 : QLOGappend(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci)
364 : {
365 5 : oid *ret = getArgReference_oid(stk, pci, 0);
366 5 : str *q = getArgReference_str(stk, pci, 1);
367 5 : str *pipe = getArgReference_str(stk, pci, 2);
368 5 : str *usr = getArgReference_str(stk, pci, 3);
369 5 : timestamp *tick = getArgReference_TYPE(stk, pci, 4, timestamp);
370 5 : oid o;
371 5 : InstrPtr sig = getInstrPtr(mb, 0);
372 5 : char buf[128], *nme = buf;
373 5 : str msg;
374 :
375 5 : (void) cntxt;
376 5 : msg = initQlog();
377 5 : if (msg)
378 : return msg;
379 5 : snprintf(buf, 128, "%s.%s", getModuleId(sig), getFunctionId(sig));
380 5 : MT_lock_set(&QLOGlock);
381 5 : o = BUNfnd(QLOG_cat_id, &mb->tag);
382 5 : if (o == BUN_NONE) {
383 5 : *ret = mb->tag;
384 10 : if (BUNappend(QLOG_cat_id, &mb->tag, false) != GDK_SUCCEED ||
385 10 : BUNappend(QLOG_cat_query, *q, false) != GDK_SUCCEED ||
386 10 : BUNappend(QLOG_cat_pipe, *pipe, false) != GDK_SUCCEED ||
387 10 : BUNappend(QLOG_cat_plan, nme, false) != GDK_SUCCEED ||
388 10 : BUNappend(QLOG_cat_mal, &mb->stop, false) != GDK_SUCCEED ||
389 10 : BUNappend(QLOG_cat_optimize, &mb->optimize, false) != GDK_SUCCEED ||
390 10 : BUNappend(QLOG_cat_user, *usr, false) != GDK_SUCCEED ||
391 5 : BUNappend(QLOG_cat_defined, tick, false) != GDK_SUCCEED) {
392 0 : MT_lock_unset(&QLOGlock);
393 0 : throw(MAL, "querylog.append", SQLSTATE(HY013) MAL_MALLOC_FAIL);
394 : }
395 : }
396 5 : if (TMsubcommit_list(commitlist, NULL, committop, -1) != GDK_SUCCEED)
397 0 : msg = createException(MAL, "querylog", GDK_EXCEPTION);
398 5 : MT_lock_unset(&QLOGlock);
399 5 : return msg;
400 : }
401 :
402 : static str
403 255211 : QLOGdefineNaive(void *ret, const char *const *qry, const char *const *opt, const int *nr)
404 : {
405 : // Nothing else to be done.
406 255211 : (void) ret;
407 255211 : (void) qry;
408 255211 : (void) opt;
409 255211 : (void) nr;
410 255211 : return MAL_SUCCEED;
411 : }
412 :
413 : static str
414 0 : QLOGcontextNaive(void *ret, const char *const *release, const char *const *version, const char *const *revision, const char *const *uri)
415 : {
416 : // Nothing else to be done.
417 0 : (void) ret;
418 0 : (void) release;
419 0 : (void) version;
420 0 : (void) revision;
421 0 : (void) uri;
422 0 : return MAL_SUCCEED;
423 : }
424 :
425 : static str
426 5 : QLOGcall(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci)
427 : {
428 5 : timestamp *tick1 = getArgReference_TYPE(stk, pci, 1, timestamp);
429 5 : timestamp *tick2 = getArgReference_TYPE(stk, pci, 2, timestamp);
430 5 : str *arg = getArgReference_str(stk, pci, 3);
431 5 : lng *tuples = getArgReference_lng(stk, pci, 4);
432 5 : lng *xtime = getArgReference_lng(stk, pci, 5);
433 5 : lng *rtime = getArgReference_lng(stk, pci, 6);
434 5 : int *cpu = getArgReference_int(stk, pci, 7);
435 5 : int *iowait = getArgReference_int(stk, pci, 8);
436 5 : str msg;
437 :
438 5 : (void) cntxt;
439 :
440 5 : msg = initQlog();
441 5 : if (msg)
442 : return msg;
443 5 : if (*xtime + *rtime < QLOGthreshold)
444 : return MAL_SUCCEED;
445 5 : MT_lock_set(&QLOGlock);
446 10 : if (BUNappend(QLOG_calls_id, &mb->tag, false) != GDK_SUCCEED ||
447 10 : BUNappend(QLOG_calls_start, tick1, false) != GDK_SUCCEED ||
448 10 : BUNappend(QLOG_calls_stop, tick2, false) != GDK_SUCCEED ||
449 10 : BUNappend(QLOG_calls_arguments, *arg, false) != GDK_SUCCEED ||
450 10 : BUNappend(QLOG_calls_tuples, tuples, false) != GDK_SUCCEED ||
451 10 : BUNappend(QLOG_calls_exec, xtime, false) != GDK_SUCCEED ||
452 10 : BUNappend(QLOG_calls_result, rtime, false) != GDK_SUCCEED ||
453 10 : BUNappend(QLOG_calls_cpuload, cpu, false) != GDK_SUCCEED ||
454 5 : BUNappend(QLOG_calls_iowait, iowait, false) != GDK_SUCCEED) {
455 0 : MT_lock_unset(&QLOGlock);
456 0 : throw(MAL, "querylog.call", SQLSTATE(HY013) MAL_MALLOC_FAIL);
457 : }
458 5 : if (TMsubcommit_list(commitlist, NULL, committop, -1) != GDK_SUCCEED)
459 0 : msg = createException(MAL, "querylog", GDK_EXCEPTION);
460 5 : MT_lock_unset(&QLOGlock);
461 5 : return msg;
462 : }
463 :
464 : #include "mel.h"
465 : mel_func querylog_init_funcs[] = {
466 : command("querylog", "enable", QLOGenableThreshold, false, "Turn on the query logger", args(0,1, arg("threshold",int))),
467 : command("querylog", "enable", QLOGenable, false, "Turn on the query logger", noargs),
468 : command("querylog", "disable", QLOGdisable, false, "Turn off the query logger", noargs),
469 : command("querylog", "isset", QLOGissetFcn, false, "Return status of query logger", args(1,1, arg("",int))),
470 : command("querylog", "empty", QLOGempty, false, "Clear the query log tables", noargs),
471 : pattern("querylog", "append", QLOGappend, false, "Add a new query call to the query log", args(0,4, arg("q",str),arg("pipe",str),arg("usr",str),arg("tick",timestamp))),
472 : command("querylog", "define", QLOGdefineNaive, false, "Noop operation, just marking the query", args(0,3, arg("q",str),arg("pipe",str),arg("size",int))),
473 : command("querylog", "context", QLOGcontextNaive, false, "Noop operation, just marking the query", args(0,4, arg("release",str),arg("version",str),arg("revision",str),arg("uri",str))),
474 : pattern("querylog", "call", QLOGcall, false, "Add a new query call to the query log", args(0,8, arg("tick1",timestamp),arg("tick2",timestamp),arg("arg",str),arg("tuples",lng),arg("xtime",lng),arg("rtime",lng),arg("cpu",int),arg("iowait",int))),
475 : { .imp=NULL }
476 : };
477 : #include "mal_import.h"
478 : #ifdef _MSC_VER
479 : #undef read
480 : #pragma section(".CRT$XCU",read)
481 : #endif
482 321 : LIB_STARTUP_FUNC(init_querylog_mal)
483 321 : { mal_module("querylog", NULL, querylog_init_funcs); }
|
