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 : /* Author(s) M.L. Kersten
14 : * The MAL Runtime Profiler and system queue
15 : * This little helper module is used to perform instruction based profiling.
16 : * The QRYqueue is only update at the start/finish of a query.
17 : * It is also the place to keep track on the number of workers
18 : * The current code relies on a scan rather than a hash.
19 : */
20 :
21 : #include "monetdb_config.h"
22 : #include "mal_utils.h"
23 : #include "mal_runtime.h"
24 : #include "mal_interpreter.h"
25 : #include "mal_function.h"
26 : #include "mal_profiler.h"
27 : #include "mal_listing.h"
28 : #include "mal_authorize.h"
29 : #include "mal_resource.h"
30 : #include "mal_internal.h"
31 : #include "mal_private.h"
32 :
33 :
34 : QueryQueue QRYqueue = NULL;
35 : size_t qsize = 0;
36 : static oid qtag = 1; // A unique query identifier
37 :
38 : UserStats USRstats = NULL;
39 : size_t usrstatscnt = 0;
40 :
41 : static inline void
42 24733 : clearUSRstats(size_t idx)
43 : {
44 24733 : USRstats[idx] = (struct USERSTAT) { 0 };
45 : }
46 :
47 : /*
48 : * Find the index of the given 'user' in USRstats.
49 : * For a new 'user' return a new free slot.
50 : * If USRstats is full, extend it.
51 : */
52 : static size_t
53 266116 : getUSRstatsIdx(MalBlkPtr mb, oid user)
54 : {
55 266116 : size_t i = 0;
56 266116 : UserStats tmp = NULL;
57 :
58 268240 : for (i = 0; i < usrstatscnt; i++)
59 : /* The array is dense, so we either find the user or an empty slot. */
60 268239 : if (USRstats[i].user == user || USRstats[i].username == NULL)
61 266115 : return i;
62 :
63 : /* expand USRstats */
64 1 : tmp = (UserStats) GDKrealloc(USRstats,
65 : sizeof(struct USERSTAT) *
66 : (size_t) (usrstatscnt += MAL_MAXCLIENTS));
67 1 : if (tmp == NULL) {
68 : /* It's not a fatal error if we can't extend USRstats.
69 : * We don't want to affect existing USRstats. */
70 0 : addMalException(mb, "getUSRstatsIdx" MAL_MALLOC_FAIL);
71 0 : return (size_t) -1;
72 : }
73 1 : USRstats = tmp;
74 5 : for (; i < usrstatscnt; i++)
75 4 : clearUSRstats(i);
76 1 : return usrstatscnt - MAL_MAXCLIENTS;
77 : }
78 :
79 : static void
80 584187 : updateUserStats(Client cntxt, MalBlkPtr mb, lng ticks, time_t started,
81 : time_t finished, str query)
82 : {
83 : // don't keep stats for context without username
84 584187 : if (cntxt->username == NULL)
85 : return;
86 :
87 266116 : size_t idx = getUSRstatsIdx(mb, cntxt->user);
88 :
89 266116 : if (idx == (size_t) -1) {
90 0 : addMalException(mb,
91 : "updateUserStats"
92 : "Failed to get an entry in user statistics");
93 0 : return;
94 : }
95 :
96 266116 : if (USRstats[idx].username == NULL || USRstats[idx].user != cntxt->user
97 265745 : || strcmp(USRstats[idx].username, cntxt->username) != 0) {
98 401 : GDKfree(USRstats[idx].username);
99 401 : GDKfree(USRstats[idx].maxquery);
100 401 : clearUSRstats(idx);
101 401 : USRstats[idx].user = cntxt->user;
102 401 : USRstats[idx].username = GDKstrdup(cntxt->username);
103 : }
104 266116 : USRstats[idx].querycount++;
105 266116 : USRstats[idx].totalticks += ticks;
106 266116 : if (ticks >= USRstats[idx].maxticks && query) {
107 1392 : USRstats[idx].started = started;
108 1392 : USRstats[idx].finished = finished;
109 1392 : USRstats[idx].maxticks = ticks;
110 1392 : GDKfree(USRstats[idx].maxquery);
111 1392 : USRstats[idx].maxquery = GDKstrdup(query);
112 : }
113 : }
114 :
115 : /*
116 : * Free up the whole USRstats before mserver5 exits.
117 : */
118 : static void
119 350 : dropUSRstats(void)
120 : {
121 350 : size_t i;
122 350 : MT_lock_set(&mal_delayLock);
123 25028 : for (i = 0; i < usrstatscnt; i++) {
124 24328 : GDKfree(USRstats[i].username);
125 24328 : GDKfree(USRstats[i].maxquery);
126 24328 : clearUSRstats(i);
127 : }
128 350 : GDKfree(USRstats);
129 350 : USRstats = NULL;
130 350 : usrstatscnt = 0;
131 350 : MT_lock_unset(&mal_delayLock);
132 350 : }
133 :
134 : static str
135 584187 : isaSQLquery(MalBlkPtr mb)
136 : {
137 584187 : if (mb) {
138 12205282 : for (int i = 1; i < mb->stop; i++) {
139 11877210 : InstrPtr p = getInstrPtr(mb, i);
140 11877210 : if (getModuleId(p) && idcmp(getModuleId(p), "querylog") == 0
141 256115 : && idcmp(getFunctionId(p), "define") == 0)
142 256115 : return getVarConstant(mb, getArg(p, 1)).val.sval;
143 : }
144 : }
145 : return NULL;
146 : }
147 :
148 : /*
149 : * Manage the runtime profiling information
150 : * It is organized as a circular buffer, head/tail.
151 : * Elements are removed from the buffer when it becomes full.
152 : * This way we keep the information a little longer for inspection.
153 : */
154 :
155 : /* clear the next entry for a new call unless it is a running query */
156 : static inline void
157 26636 : clearQRYqueue(size_t idx)
158 : {
159 26636 : QRYqueue[idx] = (struct QRYQUEUE) { 0 };
160 : }
161 :
162 : static void
163 350 : dropQRYqueue(void)
164 : {
165 350 : MT_lock_set(&mal_delayLock);
166 25830 : for (size_t i = 0; i < qsize; i++) {
167 25480 : GDKfree(QRYqueue[i].query);
168 25480 : GDKfree(QRYqueue[i].username);
169 25480 : clearQRYqueue(i);
170 : }
171 350 : GDKfree(QRYqueue);
172 350 : QRYqueue = NULL;
173 350 : qsize = 0;
174 350 : qtag = 1;
175 350 : MT_lock_unset(&mal_delayLock);
176 350 : }
177 :
178 : oid
179 255948 : runtimeProfileSetTag(Client cntxt)
180 : {
181 255948 : MT_lock_set(&mal_delayLock);
182 256513 : cntxt->curprg->def->tag = qtag++;
183 256513 : MT_lock_unset(&mal_delayLock);
184 :
185 256513 : return cntxt->curprg->def->tag;
186 : }
187 :
188 : /* At the start of every MAL block or SQL query */
189 : void
190 754902 : runtimeProfileInit(Client cntxt, MalBlkPtr mb, MalStkPtr stk)
191 : {
192 754902 : static size_t qlast = 0;
193 754902 : size_t i, paused = 0;
194 754902 : str q;
195 :
196 : /* Recursive calls don't change the query queue, but later we have to check
197 : how to stop/pause/resume queries doing recursive calls from multiple workers */
198 754902 : if (stk->up)
199 : return;
200 584140 : MT_lock_set(&mal_delayLock);
201 :
202 584187 : if (USRstats == NULL) {
203 351 : usrstatscnt = MAL_MAXCLIENTS;
204 351 : USRstats = (UserStats) GDKzalloc(sizeof(struct USERSTAT) * usrstatscnt);
205 351 : if (USRstats == NULL) {
206 0 : addMalException(mb, "runtimeProfileInit" MAL_MALLOC_FAIL);
207 0 : MT_lock_unset(&mal_delayLock);
208 0 : return;
209 : }
210 : }
211 :
212 584187 : if (QRYqueue == NULL) {
213 351 : QRYqueue = (QueryQueue) GDKzalloc(sizeof(struct QRYQUEUE) *
214 : (qsize = MAL_MAXCLIENTS));
215 :
216 351 : if (QRYqueue == NULL) {
217 0 : addMalException(mb, "runtimeProfileInit" MAL_MALLOC_FAIL);
218 0 : MT_lock_unset(&mal_delayLock);
219 0 : return;
220 : }
221 : }
222 52204807 : for (i = 0; i < qsize; i++) {
223 102917860 : paused += QRYqueue[i].status && (QRYqueue[i].status[0] == 'p' || QRYqueue[i].status[0] == 'r'); /* running, prepared or paused */
224 : }
225 584187 : if (qsize - paused < (size_t) MAL_MAXCLIENTS) {
226 19 : qsize += MAL_MAXCLIENTS;
227 19 : QueryQueue tmp;
228 19 : tmp = (QueryQueue) GDKrealloc(QRYqueue,
229 : sizeof(struct QRYQUEUE) * qsize);
230 19 : if (tmp == NULL) {
231 0 : addMalException(mb, "runtimeProfileInit" MAL_MALLOC_FAIL);
232 0 : qsize -= MAL_MAXCLIENTS; /* undo increment */
233 0 : MT_lock_unset(&mal_delayLock);
234 0 : return;
235 : }
236 19 : QRYqueue = tmp;
237 1175 : for (i = qsize - MAL_MAXCLIENTS; i < qsize; i++)
238 1156 : clearQRYqueue(i);
239 : }
240 : // add new invocation
241 584205 : for (i = 0; i < qsize; i++) {
242 584205 : size_t j = qlast;
243 584205 : if (++qlast >= qsize)
244 8092 : qlast = 0;
245 584205 : if (QRYqueue[j].stk == NULL ||
246 18 : QRYqueue[j].status == NULL ||
247 18 : (QRYqueue[j].status[0] != 'r' && QRYqueue[j].status[0] != 'p')) {
248 584187 : QRYqueue[j].mb = mb;
249 584187 : QRYqueue[j].tag = stk->tag = mb->tag;
250 584187 : QRYqueue[j].stk = stk; // for status pause 'p'/running '0'/ quitting 'q'
251 584187 : QRYqueue[j].finished = 0;
252 584187 : QRYqueue[j].start = time(0);
253 584187 : q = isaSQLquery(mb);
254 584187 : GDKfree(QRYqueue[j].query);
255 584187 : QRYqueue[j].query = GDKstrdup(q); /* NULL in, NULL out */
256 584187 : GDKfree(QRYqueue[j].username);
257 584187 : if (!GDKembedded())
258 582360 : QRYqueue[j].username = GDKstrdup(cntxt->username);
259 584187 : QRYqueue[j].idx = cntxt->idx;
260 : /* give the MB upperbound by addition of 1 MB */
261 584187 : QRYqueue[j].memory = 1 + (int) (stk->memory / LL_CONSTANT(1048576)); /* Convert to MB */
262 584187 : QRYqueue[j].workers = (int) 1; /* this is the first one */
263 584187 : QRYqueue[j].status = "running";
264 584187 : QRYqueue[j].cntxt = cntxt;
265 584187 : QRYqueue[j].ticks = GDKusec();
266 584187 : break;
267 : }
268 : }
269 584187 : MT_lock_unset(&mal_delayLock);
270 584186 : MT_lock_set(&mal_contextLock);
271 584187 : cntxt->idle = 0;
272 584187 : MT_lock_unset(&mal_contextLock);
273 : }
274 :
275 : /*
276 : * At the end of every MAL block or SQL query.
277 : *
278 : * Returning from a recursive call does not change the number of workers.
279 : */
280 : void
281 754238 : runtimeProfileFinish(Client cntxt, MalBlkPtr mb, MalStkPtr stk)
282 : {
283 754238 : size_t i;
284 754238 : bool found = false;
285 :
286 : /* Recursive calls don't change the query queue, but later we have to check
287 : how to stop/pause/resume queries doing recursive calls from multiple workers */
288 754238 : if (stk->up)
289 : return;
290 583700 : MT_lock_set(&mal_delayLock);
291 26159613 : for (i = 0; i < qsize; i++) {
292 25575426 : if (QRYqueue[i].stk == stk) {
293 584187 : if (QRYqueue[i].status[0] == 's')
294 1 : QRYqueue[i].status = "aborted";
295 : else
296 584186 : QRYqueue[i].status = "finished";
297 584187 : QRYqueue[i].finished = time(0);
298 584187 : QRYqueue[i].workers = (int) ATOMIC_GET(&mb->workers);
299 : /* give the MB upperbound by addition of 1 MB */
300 584187 : QRYqueue[i].memory = 1 + (int) (mb->memory / LL_CONSTANT(1048576));
301 584187 : QRYqueue[i].cntxt = NULL;
302 584187 : QRYqueue[i].stk = NULL;
303 584187 : QRYqueue[i].mb = NULL;
304 584187 : QRYqueue[i].ticks = GDKusec() - QRYqueue[i].ticks;
305 584187 : updateUserStats(cntxt, mb, QRYqueue[i].ticks, QRYqueue[i].start,
306 : QRYqueue[i].finished, QRYqueue[i].query);
307 : // assume that the user is now idle
308 584187 : MT_lock_unset(&mal_delayLock);
309 584186 : MT_lock_set(&mal_contextLock);
310 584187 : cntxt->idle = time(0);
311 584187 : MT_lock_unset(&mal_contextLock);
312 584187 : found = true;
313 584187 : break;
314 : }
315 : }
316 :
317 : // every query that has been started has an entry in QRYqueue. If this
318 : // finished query is not found, we want to print some informational
319 : // messages for debugging.
320 584187 : if (!found) {
321 0 : assert(0);
322 : TRC_INFO_IF(MAL_SERVER) {
323 : TRC_INFO_ENDIF(MAL_SERVER,
324 : "runtimeProfilerFinish: stk (%p) not found in QRYqueue",
325 : stk);
326 : for (i = 0; i < qsize; i++) {
327 : // print some info. of queries not "finished"
328 : if (strcmp(QRYqueue[i].status, "finished") != 0) {
329 : struct tm tmp;
330 : char tbuf[64];
331 : (void) localtime_r(&QRYqueue[i].start, &tmp);
332 : strftime(tbuf, sizeof(tbuf), "%F %T", &tmp);
333 : TRC_INFO_ENDIF(MAL_SERVER,
334 : "QRYqueue[%zu]: stk(%p), tag(" OIDFMT
335 : "), username(%s), start(%s), status(%s), query(%s)",
336 : i, QRYqueue[i].stk, QRYqueue[i].tag,
337 : QRYqueue[i].username, tbuf,
338 : QRYqueue[i].status, QRYqueue[i].query);
339 : }
340 : }
341 : }
342 754725 : MT_lock_unset(&mal_delayLock);
343 : }
344 :
345 : }
346 :
347 : /* Used by mal_reset to do the grand final clean up of this area before MonetDB exits */
348 : void
349 350 : mal_runtime_reset(void)
350 : {
351 350 : dropQRYqueue();
352 350 : dropUSRstats();
353 350 : }
354 :
355 : /* At the start of each MAL stmt */
356 : void
357 67909666 : runtimeProfileBegin(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci,
358 : RuntimeProfile prof)
359 : {
360 67909666 : (void) cntxt;
361 67909666 : (void) mb;
362 67909666 : (void) stk;
363 67909666 : (void) pci;
364 :
365 67909666 : assert(pci);
366 : /* always collect the MAL instruction execution time */
367 67909666 : prof->ticks = GDKusec();
368 67929017 : }
369 :
370 : /* At the end of each MAL stmt */
371 : void
372 67945130 : runtimeProfileExit(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci,
373 : RuntimeProfile prof)
374 : {
375 67945130 : lng ticks = GDKusec();
376 :
377 67990513 : if (profilerStatus > 0)
378 45 : profilerEvent(&(struct MalEvent) { cntxt, mb, stk, pci, ticks,
379 45 : ticks - prof->ticks },
380 : NULL);
381 67990513 : if (cntxt->sqlprofiler)
382 938 : sqlProfilerEvent(cntxt, mb, stk, pci, ticks, ticks - prof->ticks);
383 67990518 : if (profilerStatus < 0) {
384 : /* delay profiling until you encounter start of MAL function */
385 0 : if (getInstrPtr(mb, 0) == pci)
386 0 : profilerStatus = 1;
387 : }
388 67990518 : }
389 :
390 : /*
391 : * For performance evaluation it is handy to estimate the
392 : * amount of bytes produced by an instruction.
393 : * The actual amount is harder to guess, because an instruction
394 : * may trigger a side effect, such as creating a hash-index.
395 : * Side effects are ignored.
396 : */
397 :
398 : lng
399 0 : getBatSpace(BAT *b)
400 : {
401 0 : lng space = 0;
402 0 : if (b == NULL)
403 : return 0;
404 0 : space += BATcount(b) << b->tshift;
405 0 : if (space) {
406 0 : MT_lock_set(&b->theaplock);
407 0 : if (b->tvheap)
408 0 : space += heapinfo(b->tvheap, b->batCacheid);
409 0 : MT_lock_unset(&b->theaplock);
410 0 : MT_rwlock_rdlock(&b->thashlock);
411 0 : space += hashinfo(b->thash, b->batCacheid);
412 0 : MT_rwlock_rdunlock(&b->thashlock);
413 : }
414 : return space;
415 : }
416 :
417 : lng
418 0 : getVolume(MalStkPtr stk, InstrPtr pci, int rd)
419 : {
420 0 : int i, limit;
421 0 : lng vol = 0;
422 0 : BAT *b;
423 :
424 0 : if (stk == NULL)
425 : return 0;
426 0 : limit = rd ? pci->argc : pci->retc;
427 0 : i = rd ? pci->retc : 0;
428 :
429 0 : for (; i < limit; i++) {
430 0 : if (stk->stk[getArg(pci, i)].bat) {
431 0 : oid cnt = 0;
432 :
433 0 : b = BBPquickdesc(stk->stk[getArg(pci, i)].val.bval);
434 0 : if (b == NULL)
435 0 : continue;
436 0 : cnt = BATcount(b);
437 : /* Usually reading views cost as much as full bats.
438 : But when we output a slice that is not the case. */
439 0 : if (rd)
440 0 : vol += (!isVIEW(b) && !VIEWtparent(b)) ? tailsize(b, cnt) : 0;
441 0 : else if (!isVIEW(b))
442 0 : vol += tailsize(b, cnt);
443 : }
444 : }
445 : return vol;
446 : }
|
