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