LCOV - code coverage report
Current view: top level - src/backend/executor - instrument.c (source / functions) Hit Total Coverage
Test: PostgreSQL 16beta1 Lines: 131 142 92.3 %
Date: 2023-06-06 09:15:10 Functions: 13 14 92.9 %
Legend: Lines: hit not hit

          Line data    Source code
       1             : /*-------------------------------------------------------------------------
       2             :  *
       3             :  * instrument.c
       4             :  *   functions for instrumentation of plan execution
       5             :  *
       6             :  *
       7             :  * Copyright (c) 2001-2023, PostgreSQL Global Development Group
       8             :  *
       9             :  * IDENTIFICATION
      10             :  *    src/backend/executor/instrument.c
      11             :  *
      12             :  *-------------------------------------------------------------------------
      13             :  */
      14             : #include "postgres.h"
      15             : 
      16             : #include <unistd.h>
      17             : 
      18             : #include "executor/instrument.h"
      19             : 
      20             : BufferUsage pgBufferUsage;
      21             : static BufferUsage save_pgBufferUsage;
      22             : WalUsage    pgWalUsage;
      23             : static WalUsage save_pgWalUsage;
      24             : 
      25             : static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add);
      26             : static void WalUsageAdd(WalUsage *dst, WalUsage *add);
      27             : 
      28             : 
      29             : /* Allocate new instrumentation structure(s) */
      30             : Instrumentation *
      31       62796 : InstrAlloc(int n, int instrument_options, bool async_mode)
      32             : {
      33             :     Instrumentation *instr;
      34             : 
      35             :     /* initialize all fields to zeroes, then modify as needed */
      36       62796 :     instr = palloc0(n * sizeof(Instrumentation));
      37       62796 :     if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL))
      38             :     {
      39       58350 :         bool        need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
      40       58350 :         bool        need_wal = (instrument_options & INSTRUMENT_WAL) != 0;
      41       58350 :         bool        need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
      42             :         int         i;
      43             : 
      44      116700 :         for (i = 0; i < n; i++)
      45             :         {
      46       58350 :             instr[i].need_bufusage = need_buffers;
      47       58350 :             instr[i].need_walusage = need_wal;
      48       58350 :             instr[i].need_timer = need_timer;
      49       58350 :             instr[i].async_mode = async_mode;
      50             :         }
      51             :     }
      52             : 
      53       62796 :     return instr;
      54             : }
      55             : 
      56             : /* Initialize a pre-allocated instrumentation structure. */
      57             : void
      58        1650 : InstrInit(Instrumentation *instr, int instrument_options)
      59             : {
      60        1650 :     memset(instr, 0, sizeof(Instrumentation));
      61        1650 :     instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
      62        1650 :     instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
      63        1650 :     instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
      64        1650 : }
      65             : 
      66             : /* Entry to a plan node */
      67             : void
      68    12554506 : InstrStartNode(Instrumentation *instr)
      69             : {
      70    22322788 :     if (instr->need_timer &&
      71     9768282 :         !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime))
      72           0 :         elog(ERROR, "InstrStartNode called twice in a row");
      73             : 
      74             :     /* save buffer usage totals at node entry, if needed */
      75    12554506 :     if (instr->need_bufusage)
      76      284350 :         instr->bufusage_start = pgBufferUsage;
      77             : 
      78    12554506 :     if (instr->need_walusage)
      79      103930 :         instr->walusage_start = pgWalUsage;
      80    12554506 : }
      81             : 
      82             : /* Exit from a plan node */
      83             : void
      84    12552328 : InstrStopNode(Instrumentation *instr, double nTuples)
      85             : {
      86    12552328 :     double      save_tuplecount = instr->tuplecount;
      87             :     instr_time  endtime;
      88             : 
      89             :     /* count the returned tuples */
      90    12552328 :     instr->tuplecount += nTuples;
      91             : 
      92             :     /* let's update the time only if the timer was requested */
      93    12552328 :     if (instr->need_timer)
      94             :     {
      95     9766116 :         if (INSTR_TIME_IS_ZERO(instr->starttime))
      96           0 :             elog(ERROR, "InstrStopNode called without start");
      97             : 
      98     9766116 :         INSTR_TIME_SET_CURRENT(endtime);
      99     9766116 :         INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
     100             : 
     101     9766116 :         INSTR_TIME_SET_ZERO(instr->starttime);
     102             :     }
     103             : 
     104             :     /* Add delta of buffer usage since entry to node's totals */
     105    12552328 :     if (instr->need_bufusage)
     106      282184 :         BufferUsageAccumDiff(&instr->bufusage,
     107      282184 :                              &pgBufferUsage, &instr->bufusage_start);
     108             : 
     109    12552328 :     if (instr->need_walusage)
     110      101764 :         WalUsageAccumDiff(&instr->walusage,
     111      101764 :                           &pgWalUsage, &instr->walusage_start);
     112             : 
     113             :     /* Is this the first tuple of this cycle? */
     114    12552328 :     if (!instr->running)
     115             :     {
     116       88464 :         instr->running = true;
     117       88464 :         instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
     118             :     }
     119             :     else
     120             :     {
     121             :         /*
     122             :          * In async mode, if the plan node hadn't emitted any tuples before,
     123             :          * this might be the first tuple
     124             :          */
     125    12463864 :         if (instr->async_mode && save_tuplecount < 1.0)
     126           0 :             instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
     127             :     }
     128    12552328 : }
     129             : 
     130             : /* Update tuple count */
     131             : void
     132           0 : InstrUpdateTupleCount(Instrumentation *instr, double nTuples)
     133             : {
     134             :     /* count the returned tuples */
     135           0 :     instr->tuplecount += nTuples;
     136           0 : }
     137             : 
     138             : /* Finish a run cycle for a plan node */
     139             : void
     140       90268 : InstrEndLoop(Instrumentation *instr)
     141             : {
     142             :     double      totaltime;
     143             : 
     144             :     /* Skip if nothing has happened, or already shut down */
     145       90268 :     if (!instr->running)
     146        2060 :         return;
     147             : 
     148       88208 :     if (!INSTR_TIME_IS_ZERO(instr->starttime))
     149           0 :         elog(ERROR, "InstrEndLoop called on running node");
     150             : 
     151             :     /* Accumulate per-cycle statistics into totals */
     152       88208 :     totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
     153             : 
     154       88208 :     instr->startup += instr->firsttuple;
     155       88208 :     instr->total += totaltime;
     156       88208 :     instr->ntuples += instr->tuplecount;
     157       88208 :     instr->nloops += 1;
     158             : 
     159             :     /* Reset for next cycle (if any) */
     160       88208 :     instr->running = false;
     161       88208 :     INSTR_TIME_SET_ZERO(instr->starttime);
     162       88208 :     INSTR_TIME_SET_ZERO(instr->counter);
     163       88208 :     instr->firsttuple = 0;
     164       88208 :     instr->tuplecount = 0;
     165             : }
     166             : 
     167             : /* aggregate instrumentation information */
     168             : void
     169        3996 : InstrAggNode(Instrumentation *dst, Instrumentation *add)
     170             : {
     171        3996 :     if (!dst->running && add->running)
     172             :     {
     173           0 :         dst->running = true;
     174           0 :         dst->firsttuple = add->firsttuple;
     175             :     }
     176        3996 :     else if (dst->running && add->running && dst->firsttuple > add->firsttuple)
     177           0 :         dst->firsttuple = add->firsttuple;
     178             : 
     179        3996 :     INSTR_TIME_ADD(dst->counter, add->counter);
     180             : 
     181        3996 :     dst->tuplecount += add->tuplecount;
     182        3996 :     dst->startup += add->startup;
     183        3996 :     dst->total += add->total;
     184        3996 :     dst->ntuples += add->ntuples;
     185        3996 :     dst->ntuples2 += add->ntuples2;
     186        3996 :     dst->nloops += add->nloops;
     187        3996 :     dst->nfiltered1 += add->nfiltered1;
     188        3996 :     dst->nfiltered2 += add->nfiltered2;
     189             : 
     190             :     /* Add delta of buffer usage since entry to node's totals */
     191        3996 :     if (dst->need_bufusage)
     192          96 :         BufferUsageAdd(&dst->bufusage, &add->bufusage);
     193             : 
     194        3996 :     if (dst->need_walusage)
     195           0 :         WalUsageAdd(&dst->walusage, &add->walusage);
     196        3996 : }
     197             : 
     198             : /* note current values during parallel executor startup */
     199             : void
     200        2606 : InstrStartParallelQuery(void)
     201             : {
     202        2606 :     save_pgBufferUsage = pgBufferUsage;
     203        2606 :     save_pgWalUsage = pgWalUsage;
     204        2606 : }
     205             : 
     206             : /* report usage after parallel executor shutdown */
     207             : void
     208        2600 : InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
     209             : {
     210        2600 :     memset(bufusage, 0, sizeof(BufferUsage));
     211        2600 :     BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage);
     212        2600 :     memset(walusage, 0, sizeof(WalUsage));
     213        2600 :     WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage);
     214        2600 : }
     215             : 
     216             : /* accumulate work done by workers in leader's stats */
     217             : void
     218        2600 : InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
     219             : {
     220        2600 :     BufferUsageAdd(&pgBufferUsage, bufusage);
     221        2600 :     WalUsageAdd(&pgWalUsage, walusage);
     222        2600 : }
     223             : 
     224             : /* dst += add */
     225             : static void
     226        2696 : BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
     227             : {
     228        2696 :     dst->shared_blks_hit += add->shared_blks_hit;
     229        2696 :     dst->shared_blks_read += add->shared_blks_read;
     230        2696 :     dst->shared_blks_dirtied += add->shared_blks_dirtied;
     231        2696 :     dst->shared_blks_written += add->shared_blks_written;
     232        2696 :     dst->local_blks_hit += add->local_blks_hit;
     233        2696 :     dst->local_blks_read += add->local_blks_read;
     234        2696 :     dst->local_blks_dirtied += add->local_blks_dirtied;
     235        2696 :     dst->local_blks_written += add->local_blks_written;
     236        2696 :     dst->temp_blks_read += add->temp_blks_read;
     237        2696 :     dst->temp_blks_written += add->temp_blks_written;
     238        2696 :     INSTR_TIME_ADD(dst->blk_read_time, add->blk_read_time);
     239        2696 :     INSTR_TIME_ADD(dst->blk_write_time, add->blk_write_time);
     240        2696 :     INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
     241        2696 :     INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
     242        2696 : }
     243             : 
     244             : /* dst += add - sub */
     245             : void
     246      323866 : BufferUsageAccumDiff(BufferUsage *dst,
     247             :                      const BufferUsage *add,
     248             :                      const BufferUsage *sub)
     249             : {
     250      323866 :     dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
     251      323866 :     dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
     252      323866 :     dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
     253      323866 :     dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
     254      323866 :     dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
     255      323866 :     dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
     256      323866 :     dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
     257      323866 :     dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
     258      323866 :     dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
     259      323866 :     dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
     260      323866 :     INSTR_TIME_ACCUM_DIFF(dst->blk_read_time,
     261             :                           add->blk_read_time, sub->blk_read_time);
     262      323866 :     INSTR_TIME_ACCUM_DIFF(dst->blk_write_time,
     263             :                           add->blk_write_time, sub->blk_write_time);
     264      323866 :     INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
     265             :                           add->temp_blk_read_time, sub->temp_blk_read_time);
     266      323866 :     INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,
     267             :                           add->temp_blk_write_time, sub->temp_blk_write_time);
     268      323866 : }
     269             : 
     270             : /* helper functions for WAL usage accumulation */
     271             : static void
     272        2600 : WalUsageAdd(WalUsage *dst, WalUsage *add)
     273             : {
     274        2600 :     dst->wal_bytes += add->wal_bytes;
     275        2600 :     dst->wal_records += add->wal_records;
     276        2600 :     dst->wal_fpi += add->wal_fpi;
     277        2600 : }
     278             : 
     279             : void
     280      166802 : WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
     281             : {
     282      166802 :     dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
     283      166802 :     dst->wal_records += add->wal_records - sub->wal_records;
     284      166802 :     dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
     285      166802 : }

Generated by: LCOV version 1.14