LCOV - code coverage report
Current view: top level - monetdb5/mal - mal_runtime.c (source / functions) Hit Total Coverage
Test: coverage.info Lines: 217 265 81.9 %
Date: 2021-09-14 22:17:06 Functions: 13 15 86.7 %

          Line data    Source code
       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 - 2021 MonetDB B.V.
       7             :  */
       8             : 
       9             : /* Author(s) M.L. Kersten
      10             :  * The MAL Runtime Profiler and system queue
      11             :  * This little helper module is used to perform instruction based profiling.
      12             :  * The QRYqueue is only update at the start/finish of a query.
      13             :  * It is also the place to keep track on the number of workers
      14             :  * The current code relies on a scan rather than a hash.
      15             :  */
      16             : 
      17             : #include "monetdb_config.h"
      18             : #include "mal_utils.h"
      19             : #include "mal_runtime.h"
      20             : #include "mal_interpreter.h"
      21             : #include "mal_function.h"
      22             : #include "mal_profiler.h"
      23             : #include "mal_listing.h"
      24             : #include "mal_authorize.h"
      25             : #include "mal_resource.h"
      26             : #include "mal_private.h"
      27             : 
      28             : 
      29             : QueryQueue QRYqueue = NULL;
      30             : size_t qsize = 0, qhead = 0, qtail = 0;
      31             : static oid qtag= 1;             // A unique query identifier
      32             : 
      33             : UserStats  USRstats = NULL;
      34             : size_t usrstatscnt = 0;
      35             : 
      36             : static void
      37       16844 : clearUSRstats(size_t idx)
      38             : {
      39       16844 :         USRstats[idx].user= 0;
      40       16844 :         USRstats[idx].username = 0;
      41       16844 :         USRstats[idx].querycount = 0;
      42       16844 :         USRstats[idx].totalticks = 0;
      43       16844 :         USRstats[idx].started = 0;
      44       16844 :         USRstats[idx].finished = 0;
      45       16844 :         USRstats[idx].maxticks = 0;
      46       16844 :         USRstats[idx].maxquery = 0;
      47       16844 : }
      48             : 
      49             : /*
      50             :  * Find the index of the given 'user' in USRstats.
      51             :  * For a new 'user' return a new free slot.
      52             :  * If USRstats is full, extend it.
      53             :  */
      54             : static
      55             : size_t
      56      364022 : getUSRstatsIdx(MalBlkPtr mb, oid user)
      57             : {
      58             :         size_t i = 0;
      59             :         UserStats tmp = NULL;
      60             : 
      61      367906 :         for (i = 0; i < usrstatscnt; i++)
      62             :                 /* The array is dense, so we either find the user or an empty slot. */
      63      367905 :                 if (USRstats[i].user == user || USRstats[i].username == NULL)
      64      364021 :                         return i;
      65             : 
      66             :         /* expand USRstats */
      67           1 :         tmp = (UserStats) GDKrealloc(USRstats, sizeof (struct USERSTAT) * (size_t) (usrstatscnt += MAL_MAXCLIENTS));
      68           1 :         if (tmp == NULL) {
      69             :                 /* It's not a fatal error if we can't extend USRstats.
      70             :                  * We don't want to affect existing USRstats. */
      71           0 :                 addMalException(mb,"getUSRstatsIdx" MAL_MALLOC_FAIL);
      72           0 :                 return (size_t) -1;
      73             :         }
      74           1 :         USRstats = tmp;
      75           5 :         for ( ; i < usrstatscnt; i++)
      76           4 :                 clearUSRstats(i);
      77           1 :         return usrstatscnt - MAL_MAXCLIENTS;
      78             : }
      79             : 
      80             : static
      81             : void
      82      364022 : updateUserStats(Client cntxt, MalBlkPtr mb, lng ticks, time_t started, time_t finished, str query)
      83             : {
      84      364022 :         size_t idx = getUSRstatsIdx(mb, cntxt->user);
      85             : 
      86      364022 :         if (idx == (size_t) -1) {
      87           0 :                 addMalException(mb, "updateUserStats" "Failed to get an entry in user statistics");
      88           0 :                 return;
      89             :         }
      90             : 
      91      364022 :         if (USRstats[idx].username == NULL) {
      92        1868 :                 USRstats[idx].user = cntxt->user;
      93        1868 :                 USRstats[idx].username = GDKstrdup(cntxt->username);
      94             :         }
      95      364022 :         USRstats[idx].querycount++;
      96      364022 :         USRstats[idx].totalticks += ticks;
      97      364022 :         if( ticks >= USRstats[idx].maxticks && query){
      98        1045 :                 USRstats[idx].started = started;
      99        1045 :                 USRstats[idx].finished = finished;
     100        1045 :                 USRstats[idx].maxticks = ticks;
     101        1045 :                 GDKfree(USRstats[idx].maxquery);
     102        1045 :                 USRstats[idx].maxquery= GDKstrdup(query);
     103             :         }
     104             : }
     105             : 
     106             : /*
     107             :  * Free up the whole USRstats before mserver5 exits.
     108             :  */
     109             : static void
     110         264 : dropUSRstats(void)
     111             : {
     112             :         size_t i;
     113         264 :         MT_lock_set(&mal_delayLock);
     114       17104 :         for(i = 0; i < usrstatscnt; i++){
     115       16840 :                 GDKfree(USRstats[i].username);
     116       16840 :                 GDKfree(USRstats[i].maxquery);
     117       16840 :                 clearUSRstats(i);
     118             :         }
     119         264 :         GDKfree(USRstats);
     120         264 :         USRstats = NULL;
     121         264 :         MT_lock_unset(&mal_delayLock);
     122         264 : }
     123             : 
     124             : static str
     125      364118 : isaSQLquery(MalBlkPtr mb){
     126             :         int i;
     127             :         InstrPtr p;
     128      364118 :         if (mb)
     129     9208308 :         for ( i = 1; i< mb->stop; i++){
     130     8959718 :                 p = getInstrPtr(mb,i);
     131     8959718 :                 if ( getModuleId(p) && idcmp(getModuleId(p), "querylog") == 0 && idcmp(getFunctionId(p),"define")==0)
     132      115528 :                         return getVarConstant(mb,getArg(p,1)).val.sval;
     133             :         }
     134             :         return NULL;
     135             : }
     136             : 
     137             : /*
     138             :  * Manage the runtime profiling information
     139             :  * It is organized as a circular buffer, head/tail.
     140             :  * Elements are removed from the buffer when it becomes full.
     141             :  * This way we keep the information a little longer for inspection.
     142             :  */
     143             : 
     144             : /* clear the next entry for a new call unless it is a running query */
     145             : static void
     146      127215 : clearQRYqueue(size_t idx)
     147             : {
     148      127215 :                 QRYqueue[idx].query = 0;
     149      127215 :                 QRYqueue[idx].cntxt = 0;
     150      127215 :                 QRYqueue[idx].username = 0;
     151      127215 :                 QRYqueue[idx].idx = 0;
     152      127215 :                 QRYqueue[idx].memory = 0;
     153      127215 :                 QRYqueue[idx].tag = 0;
     154      127215 :                 QRYqueue[idx].status =0;
     155      127215 :                 QRYqueue[idx].finished = 0;
     156      127215 :                 QRYqueue[idx].start = 0;
     157      127215 :                 QRYqueue[idx].stk =0;
     158      127215 :                 QRYqueue[idx].mb =0;
     159      127215 : }
     160             : 
     161             : static void
     162      364118 : advanceQRYqueue(void)
     163             : {
     164             :         bool found_empty_slot = false;
     165             : 
     166      364118 :         while (!found_empty_slot) {
     167      364193 :                 qhead++;
     168      364193 :                 if( qhead == qsize)
     169        5762 :                         qhead = 0;
     170      364193 :                 if( qtail == qhead)
     171      349774 :                         qtail++;
     172      364193 :                 if( qtail == qsize)
     173        5544 :                         qtail = 0;
     174             :                 /* clean out the element */
     175      364193 :                 str s = QRYqueue[qhead].query;
     176      364193 :                 if (!s || QRYqueue[qhead].status == 0 || (QRYqueue[qhead].status[0] != 'r' && QRYqueue[qhead].status[0] != 'p')) {
     177             :                         /* don't wipe them when they are still running, prepared, or paused */
     178             :                         /* The upper layer has assured there is at least one slot available */
     179      364118 :                         if (s) {
     180      107171 :                                 GDKfree(s);
     181      107171 :                                 GDKfree(QRYqueue[qhead].username);
     182      107171 :                                 clearQRYqueue(qhead);
     183             :                         }
     184             :                         found_empty_slot = true;
     185             :                 }
     186             :         }
     187      364118 : }
     188             : 
     189             : static void
     190         264 : dropQRYqueue(void)
     191             : {
     192             :         size_t i;
     193         264 :         MT_lock_set(&mal_delayLock);
     194       18704 :         for(i = 0; i < qsize; i++){
     195       18440 :                 GDKfree(QRYqueue[i].query);
     196       18440 :                 GDKfree(QRYqueue[i].username);
     197       18440 :                 clearQRYqueue(i);
     198             :         }
     199         264 :         GDKfree(QRYqueue);
     200         264 :         QRYqueue = NULL;
     201         264 :         MT_lock_unset(&mal_delayLock);
     202         264 : }
     203             : 
     204             : /* At the start of every MAL block or SQL query */
     205             : void
     206      402764 : runtimeProfileInit(Client cntxt, MalBlkPtr mb, MalStkPtr stk)
     207             : {
     208             :         size_t i, paused = 0;
     209             :         str q;
     210             : 
     211      402764 :         MT_lock_set(&mal_delayLock);
     212             : 
     213      402774 :         if(USRstats == NULL){
     214         265 :                 usrstatscnt = MAL_MAXCLIENTS;
     215         265 :                 USRstats = (UserStats) GDKzalloc( sizeof (struct USERSTAT) * usrstatscnt);
     216         265 :                 if(USRstats == NULL) {
     217           0 :                         addMalException(mb,"runtimeProfileInit" MAL_MALLOC_FAIL);
     218           0 :                         MT_lock_unset(&mal_delayLock);
     219           0 :                         return;
     220             :                 }
     221             :         }
     222             : 
     223      402774 :         if ( QRYqueue == NULL) {
     224         265 :                 QRYqueue = (QueryQueue) GDKzalloc( sizeof (struct QRYQUEUE) * (qsize= MAL_MAXCLIENTS));
     225             : 
     226         265 :                 if ( QRYqueue == NULL){
     227           0 :                         addMalException(mb,"runtimeProfileInit" MAL_MALLOC_FAIL);
     228           0 :                         MT_lock_unset(&mal_delayLock);
     229           0 :                         return;
     230             :                 }
     231             :         }
     232      402774 :         assert(qhead < qsize);
     233             :         // check for recursive call, which does not change the number of workers
     234      402774 :         if (stk->up) {
     235       38752 :                 i = qtail;
     236     3212379 :                 while (i != qhead) {
     237     3173531 :                         if (QRYqueue[i].mb && QRYqueue[i].stk == stk->up) {
     238       38656 :                                 QRYqueue[i].stk = stk;
     239       38656 :                                 mb->tag = stk->tag = qtag++;
     240       38656 :                                 MT_lock_unset(&mal_delayLock);
     241       38656 :                                 return;
     242             :                         }
     243     3134875 :                         if (++i >= qsize)
     244             :                                 i = 0;
     245             :                 }
     246             : //              assert(0);
     247             :         }
     248      364118 :         i=qtail;
     249    23314100 :         while (i != qhead){
     250    22949982 :                 paused += QRYqueue[i].status && (QRYqueue[i].status[0] == 'p' || QRYqueue[i].status[0] == 'r'); /* running, prepared or paused */
     251    22949982 :                 if (++i >= qsize)
     252             :                         i = 0;
     253             :         }
     254      364118 :         if( qsize - paused < (size_t) MAL_MAXCLIENTS){
     255          26 :                 qsize += MAL_MAXCLIENTS;
     256             :                 QueryQueue tmp;
     257          26 :                 tmp = (QueryQueue) GDKrealloc( QRYqueue, sizeof (struct QRYQUEUE) * qsize);
     258          26 :                 if ( tmp == NULL){
     259           0 :                         addMalException(mb,"runtimeProfileInit" MAL_MALLOC_FAIL);
     260           0 :                         qsize -= MAL_MAXCLIENTS; /* undo increment */
     261           0 :                         MT_lock_unset(&mal_delayLock);
     262           0 :                         return;
     263             :                 }
     264          26 :                 QRYqueue = tmp;
     265        1630 :                 for (i = qsize - MAL_MAXCLIENTS; i < qsize; i++)
     266        1604 :                         clearQRYqueue(i);
     267             :         }
     268             : 
     269             :         // add new invocation
     270      364118 :         cntxt->idle = 0;
     271      364118 :         QRYqueue[qhead].mb = mb;
     272      364118 :         QRYqueue[qhead].tag = qtag++;
     273      364118 :         QRYqueue[qhead].stk = stk;                              // for status pause 'p'/running '0'/ quiting 'q'
     274      364118 :         QRYqueue[qhead].finished = 0;
     275      364118 :         QRYqueue[qhead].start = time(0);
     276      364118 :         q = isaSQLquery(mb);
     277      364118 :         QRYqueue[qhead].query = q? GDKstrdup(q):0;
     278      364118 :         GDKfree(QRYqueue[qhead].username);
     279      364118 :         if (!GDKembedded())
     280      362567 :                 QRYqueue[qhead].username = GDKstrdup(cntxt->username);
     281      364118 :         QRYqueue[qhead].idx = cntxt->idx;
     282             :         /* give the MB upperbound by addition of 1 MB */
     283      364118 :         QRYqueue[qhead].memory = 1 + (int) (stk->memory / LL_CONSTANT(1048576)); /* Convert to MB */
     284      364118 :         QRYqueue[qhead].workers = (int) 1;      /* this is the first one */
     285      364118 :         QRYqueue[qhead].status = "running";
     286      364118 :         QRYqueue[qhead].cntxt = cntxt;
     287      364118 :         QRYqueue[qhead].ticks = GDKusec();
     288      364118 :         stk->tag = mb->tag = QRYqueue[qhead].tag;
     289      364118 :         advanceQRYqueue();
     290      364118 :         MT_lock_unset(&mal_delayLock);
     291             : }
     292             : 
     293             : /*
     294             :  * At the end of every MAL block or SQL query.
     295             :  *
     296             :  * Returning from a recursive call does not change the number of workers.
     297             :  */
     298             : void
     299      402766 : runtimeProfileFinish(Client cntxt, MalBlkPtr mb, MalStkPtr stk)
     300             : {
     301             :         size_t i;
     302             :         bool found = false;
     303             : 
     304      402766 :         MT_lock_set(&mal_delayLock);
     305      402774 :         i=qtail;
     306    26531315 :         while (i != qhead){
     307    26128541 :                 if ( QRYqueue[i].stk == stk){
     308      402774 :                         if( stk->up){
     309             :                                 // recursive call
     310       38752 :                                 QRYqueue[i].stk = stk->up;
     311       38752 :                                 mb->tag = stk->tag;
     312             :                                 break;
     313             :                         }
     314      364022 :                         QRYqueue[i].status = "finished";
     315      364022 :                         QRYqueue[i].finished = time(0);
     316      364022 :                         QRYqueue[i].workers = mb->workers;
     317             :                         /* give the MB upperbound by addition of 1 MB */
     318      364022 :                         QRYqueue[i].memory = 1 + (int)(mb->memory / LL_CONSTANT(1048576));
     319      364022 :                         QRYqueue[i].cntxt = 0;
     320      364022 :                         QRYqueue[i].stk = 0;
     321      364022 :                         QRYqueue[i].mb = 0;
     322      364022 :                         QRYqueue[i].ticks = GDKusec() - QRYqueue[i].ticks;
     323      364022 :                         updateUserStats(cntxt, mb, QRYqueue[i].ticks, QRYqueue[i].start, QRYqueue[i].finished, QRYqueue[i].query);
     324             :                         // assume that the user is now idle
     325      364022 :                         cntxt->idle = time(0);
     326             :                         found = true;
     327             :                         break;
     328             :                 }
     329    25725767 :                 i++;
     330    25725767 :                 if ( i >= qsize)
     331             :                         i = 0;
     332             :         }
     333             : 
     334             :         // every query that has been started has an entry in QRYqueue.  If this
     335             :         // finished query is not found, we want to print some informational
     336             :         // messages for debugging.
     337             :         if (!found) {
     338       38752 :                 TRC_INFO_IF(MAL_SERVER) {
     339           0 :                         TRC_INFO_ENDIF(MAL_SERVER, "runtimeProfilerFinish: stk (%p) not found in QRYqueue", stk);
     340           0 :                         i = qtail;
     341           0 :                         while (i != qhead){
     342             :                                 // print some info. of queries not "finished"
     343           0 :                                 if (strcmp(QRYqueue[i].status, "finished") != 0) {
     344           0 :                                         TRC_INFO_ENDIF(MAL_SERVER, "QRYqueue[%zu]: stk(%p), tag("OIDFMT"), username(%s), start(%ld), status(%s), query(%s)",
     345             :                                                                    i, QRYqueue[i].stk, QRYqueue[i].tag,
     346             :                                                                    QRYqueue[i].username, QRYqueue[i].start,
     347             :                                                                    QRYqueue[i].status, QRYqueue[i].query);
     348             :                                 }
     349           0 :                                 i++;
     350           0 :                                 if ( i >= qsize)
     351             :                                         i = 0;
     352             :                         }
     353             :                 }
     354             :         }
     355             : 
     356      402774 :         MT_lock_unset(&mal_delayLock);
     357      402774 : }
     358             : 
     359             : /* Used by mal_reset to do the grand final clean up of this area before MonetDB exits */
     360             : void
     361         264 : mal_runtime_reset(void)
     362             : {
     363         264 :         dropQRYqueue();
     364         264 :         qsize = 0;
     365         264 :         qtag= 1;
     366         264 :         qhead = 0;
     367         264 :         qtail = 0;
     368             : 
     369         264 :         dropUSRstats();
     370         264 :         usrstatscnt = 0;
     371         264 : }
     372             : 
     373             : /*
     374             :  * Each MAL instruction is executed by a single thread, which means we can
     375             :  * keep a simple working set around to make Stethscope attachement easy.
     376             :  * The entries are privately accessed and only can be influenced by a starting stehoscope to emit work in progress.
     377             :  */
     378             : Workingset workingset[THREADS];
     379             : 
     380             : /* At the start of each MAL stmt */
     381             : void
     382    65566053 : runtimeProfileBegin(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, RuntimeProfile prof)
     383             : {
     384    65566053 :         int tid = THRgettid();
     385             : 
     386    65567121 :         assert(pci);
     387             :         /* keep track on the instructions taken in progress for stethoscope*/
     388    65567121 :         if( tid > 0 && tid <= THREADS){
     389    65601829 :                 tid--;
     390    65601829 :                 if( malProfileMode) {
     391          45 :                         MT_lock_set(&mal_profileLock);
     392          45 :                         workingset[tid].cntxt = cntxt;
     393          45 :                         workingset[tid].mb = mb;
     394          45 :                         workingset[tid].stk = stk;
     395          45 :                         workingset[tid].pci = pci;
     396          45 :                         MT_lock_unset(&mal_profileLock);
     397             :                 } else{
     398    65601784 :                         workingset[tid].cntxt = cntxt;
     399    65601784 :                         workingset[tid].mb = mb;
     400    65601784 :                         workingset[tid].stk = stk;
     401    65601784 :                         workingset[tid].pci = pci;
     402             :                 }
     403             :         }
     404             :         /* always collect the MAL instruction execution time */
     405    65567121 :         pci->clock = prof->ticks = GDKusec();
     406             : 
     407             :         /* emit the instruction upon start as well */
     408    65621201 :         if(malProfileMode > 0 )
     409          45 :                 profilerEvent(cntxt, mb, stk, pci, TRUE);
     410    65621201 : }
     411             : 
     412             : /* At the end of each MAL stmt */
     413             : void
     414    65527909 : runtimeProfileExit(Client cntxt, MalBlkPtr mb, MalStkPtr stk, InstrPtr pci, RuntimeProfile prof)
     415             : {
     416    65527909 :         int tid = THRgettid();
     417    65509768 :         lng ticks = GDKusec();
     418             : 
     419             :         /* keep track on the instructions in progress*/
     420    65561794 :         if ( tid > 0 && tid <= THREADS) {
     421    65558279 :                 tid--;
     422    65558279 :                 if( malProfileMode) {
     423          45 :                         MT_lock_set(&mal_profileLock);
     424          45 :                         workingset[tid].cntxt = 0;
     425          45 :                         workingset[tid].mb = 0;
     426          45 :                         workingset[tid].stk = 0;
     427          45 :                         workingset[tid].pci = 0;
     428          45 :                         MT_lock_unset(&mal_profileLock);
     429             :                 } else{
     430    65558234 :                         workingset[tid].cntxt = 0;
     431    65558234 :                         workingset[tid].mb = 0;
     432    65558234 :                         workingset[tid].stk = 0;
     433    65558234 :                         workingset[tid].pci = 0;
     434             :                 }
     435             :         }
     436             : 
     437             :         /* always collect the MAL instruction execution time */
     438    65561794 :         pci->clock = ticks;
     439    65561794 :         pci->ticks = ticks - prof->ticks;
     440    65561794 :         pci->totticks += pci->ticks;
     441    65561794 :         pci->calls++;
     442             : 
     443    65561794 :         if(malProfileMode > 0 )
     444          45 :                 profilerEvent(cntxt, mb, stk, pci, FALSE);
     445    65561794 :         if( cntxt->sqlprofiler )
     446         958 :                 sqlProfilerEvent(cntxt, mb, stk, pci);
     447    65561797 :         if( malProfileMode < 0){
     448             :                 /* delay profiling until you encounter start of MAL function */
     449           0 :                 if( getInstrPtr(mb,0) == pci)
     450           0 :                         malProfileMode = 1;
     451             :         }
     452    65561797 : }
     453             : 
     454             : /*
     455             :  * For performance evaluation it is handy to estimate the
     456             :  * amount of bytes produced by an instruction.
     457             :  * The actual amount is harder to guess, because an instruction
     458             :  * may trigger a side effect, such as creating a hash-index.
     459             :  * Side effects are ignored.
     460             :  */
     461             : 
     462             : lng
     463           0 : getBatSpace(BAT *b){
     464             :         lng space=0;
     465           0 :         if( b == NULL)
     466             :                 return 0;
     467           0 :         space += BATcount(b) << b->tshift;
     468           0 :         if( space){
     469           0 :                 MT_lock_set(&b->theaplock);
     470           0 :                 if( b->tvheap) space += heapinfo(b->tvheap, b->batCacheid);
     471           0 :                 MT_lock_unset(&b->theaplock);
     472           0 :                 MT_rwlock_rdlock(&b->thashlock);
     473           0 :                 space += hashinfo(b->thash, b->batCacheid);
     474           0 :                 MT_rwlock_rdunlock(&b->thashlock);
     475           0 :                 space += IMPSimprintsize(b);
     476             :         }
     477             :         return space;
     478             : }
     479             : 
     480           0 : lng getVolume(MalStkPtr stk, InstrPtr pci, int rd)
     481             : {
     482             :         int i, limit;
     483             :         lng vol = 0;
     484             :         BAT *b;
     485             : 
     486           0 :         if( stk == NULL)
     487             :                 return 0;
     488           0 :         limit = rd ? pci->argc : pci->retc;
     489           0 :         i = rd ? pci->retc : 0;
     490             : 
     491           0 :         for (; i < limit; i++) {
     492           0 :                 if (stk->stk[getArg(pci, i)].vtype == TYPE_bat) {
     493             :                         oid cnt = 0;
     494             : 
     495           0 :                         b = BBPquickdesc(stk->stk[getArg(pci, i)].val.bval);
     496           0 :                         if (b == NULL)
     497           0 :                                 continue;
     498           0 :                         cnt = BATcount(b);
     499             :                         /* Usually reading views cost as much as full bats.
     500             :                            But when we output a slice that is not the case. */
     501           0 :                         if( rd)
     502           0 :                                 vol += (!isVIEW(b) && !VIEWtparent(b)) ? tailsize(b, cnt) : 0;
     503             :                         else
     504           0 :                         if( !isVIEW(b))
     505           0 :                                 vol += tailsize(b, cnt);
     506             :                 }
     507             :         }
     508             :         return vol;
     509             : }

Generated by: LCOV version 1.14