LCOV - code coverage report
Current view: top level - src/backend/executor - instrument.c (source / functions) Hit Total Coverage
Test: PostgreSQL 18devel Lines: 138 146 94.5 %
Date: 2024-12-03 07:14:52 Functions: 14 14 100.0 %
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-2024, 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       82402 : 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       82402 :     instr = palloc0(n * sizeof(Instrumentation));
      37       82402 :     if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL))
      38             :     {
      39       77522 :         bool        need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
      40       77522 :         bool        need_wal = (instrument_options & INSTRUMENT_WAL) != 0;
      41       77522 :         bool        need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
      42             :         int         i;
      43             : 
      44      155044 :         for (i = 0; i < n; i++)
      45             :         {
      46       77522 :             instr[i].need_bufusage = need_buffers;
      47       77522 :             instr[i].need_walusage = need_wal;
      48       77522 :             instr[i].need_timer = need_timer;
      49       77522 :             instr[i].async_mode = async_mode;
      50             :         }
      51             :     }
      52             : 
      53       82402 :     return instr;
      54             : }
      55             : 
      56             : /* Initialize a pre-allocated instrumentation structure. */
      57             : void
      58        1680 : InstrInit(Instrumentation *instr, int instrument_options)
      59             : {
      60        1680 :     memset(instr, 0, sizeof(Instrumentation));
      61        1680 :     instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
      62        1680 :     instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
      63        1680 :     instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
      64        1680 : }
      65             : 
      66             : /* Entry to a plan node */
      67             : void
      68    12989234 : InstrStartNode(Instrumentation *instr)
      69             : {
      70    23135268 :     if (instr->need_timer &&
      71    10146034 :         !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    12989234 :     if (instr->need_bufusage)
      76      321968 :         instr->bufusage_start = pgBufferUsage;
      77             : 
      78    12989234 :     if (instr->need_walusage)
      79      141464 :         instr->walusage_start = pgWalUsage;
      80    12989234 : }
      81             : 
      82             : /* Exit from a plan node */
      83             : void
      84    12986268 : InstrStopNode(Instrumentation *instr, double nTuples)
      85             : {
      86    12986268 :     double      save_tuplecount = instr->tuplecount;
      87             :     instr_time  endtime;
      88             : 
      89             :     /* count the returned tuples */
      90    12986268 :     instr->tuplecount += nTuples;
      91             : 
      92             :     /* let's update the time only if the timer was requested */
      93    12986268 :     if (instr->need_timer)
      94             :     {
      95    10143080 :         if (INSTR_TIME_IS_ZERO(instr->starttime))
      96           0 :             elog(ERROR, "InstrStopNode called without start");
      97             : 
      98    10143080 :         INSTR_TIME_SET_CURRENT(endtime);
      99    10143080 :         INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
     100             : 
     101    10143080 :         INSTR_TIME_SET_ZERO(instr->starttime);
     102             :     }
     103             : 
     104             :     /* Add delta of buffer usage since entry to node's totals */
     105    12986268 :     if (instr->need_bufusage)
     106      319014 :         BufferUsageAccumDiff(&instr->bufusage,
     107      319014 :                              &pgBufferUsage, &instr->bufusage_start);
     108             : 
     109    12986268 :     if (instr->need_walusage)
     110      138510 :         WalUsageAccumDiff(&instr->walusage,
     111      138510 :                           &pgWalUsage, &instr->walusage_start);
     112             : 
     113             :     /* Is this the first tuple of this cycle? */
     114    12986268 :     if (!instr->running)
     115             :     {
     116      119726 :         instr->running = true;
     117      119726 :         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    12866542 :         if (instr->async_mode && save_tuplecount < 1.0)
     126           0 :             instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
     127             :     }
     128    12986268 : }
     129             : 
     130             : /* Update tuple count */
     131             : void
     132           2 : InstrUpdateTupleCount(Instrumentation *instr, double nTuples)
     133             : {
     134             :     /* count the returned tuples */
     135           2 :     instr->tuplecount += nTuples;
     136           2 : }
     137             : 
     138             : /* Finish a run cycle for a plan node */
     139             : void
     140      121638 : InstrEndLoop(Instrumentation *instr)
     141             : {
     142             :     double      totaltime;
     143             : 
     144             :     /* Skip if nothing has happened, or already shut down */
     145      121638 :     if (!instr->running)
     146        2234 :         return;
     147             : 
     148      119404 :     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      119404 :     totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
     153             : 
     154      119404 :     instr->startup += instr->firsttuple;
     155      119404 :     instr->total += totaltime;
     156      119404 :     instr->ntuples += instr->tuplecount;
     157      119404 :     instr->nloops += 1;
     158             : 
     159             :     /* Reset for next cycle (if any) */
     160      119404 :     instr->running = false;
     161      119404 :     INSTR_TIME_SET_ZERO(instr->starttime);
     162      119404 :     INSTR_TIME_SET_ZERO(instr->counter);
     163      119404 :     instr->firsttuple = 0;
     164      119404 :     instr->tuplecount = 0;
     165             : }
     166             : 
     167             : /* aggregate instrumentation information */
     168             : void
     169        4056 : InstrAggNode(Instrumentation *dst, Instrumentation *add)
     170             : {
     171        4056 :     if (!dst->running && add->running)
     172             :     {
     173           0 :         dst->running = true;
     174           0 :         dst->firsttuple = add->firsttuple;
     175             :     }
     176        4056 :     else if (dst->running && add->running && dst->firsttuple > add->firsttuple)
     177           0 :         dst->firsttuple = add->firsttuple;
     178             : 
     179        4056 :     INSTR_TIME_ADD(dst->counter, add->counter);
     180             : 
     181        4056 :     dst->tuplecount += add->tuplecount;
     182        4056 :     dst->startup += add->startup;
     183        4056 :     dst->total += add->total;
     184        4056 :     dst->ntuples += add->ntuples;
     185        4056 :     dst->ntuples2 += add->ntuples2;
     186        4056 :     dst->nloops += add->nloops;
     187        4056 :     dst->nfiltered1 += add->nfiltered1;
     188        4056 :     dst->nfiltered2 += add->nfiltered2;
     189             : 
     190             :     /* Add delta of buffer usage since entry to node's totals */
     191        4056 :     if (dst->need_bufusage)
     192          96 :         BufferUsageAdd(&dst->bufusage, &add->bufusage);
     193             : 
     194        4056 :     if (dst->need_walusage)
     195           0 :         WalUsageAdd(&dst->walusage, &add->walusage);
     196        4056 : }
     197             : 
     198             : /* note current values during parallel executor startup */
     199             : void
     200        2712 : InstrStartParallelQuery(void)
     201             : {
     202        2712 :     save_pgBufferUsage = pgBufferUsage;
     203        2712 :     save_pgWalUsage = pgWalUsage;
     204        2712 : }
     205             : 
     206             : /* report usage after parallel executor shutdown */
     207             : void
     208        2700 : InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
     209             : {
     210        2700 :     memset(bufusage, 0, sizeof(BufferUsage));
     211        2700 :     BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage);
     212        2700 :     memset(walusage, 0, sizeof(WalUsage));
     213        2700 :     WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage);
     214        2700 : }
     215             : 
     216             : /* accumulate work done by workers in leader's stats */
     217             : void
     218        2700 : InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
     219             : {
     220        2700 :     BufferUsageAdd(&pgBufferUsage, bufusage);
     221        2700 :     WalUsageAdd(&pgWalUsage, walusage);
     222        2700 : }
     223             : 
     224             : /* dst += add */
     225             : static void
     226        2796 : BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
     227             : {
     228        2796 :     dst->shared_blks_hit += add->shared_blks_hit;
     229        2796 :     dst->shared_blks_read += add->shared_blks_read;
     230        2796 :     dst->shared_blks_dirtied += add->shared_blks_dirtied;
     231        2796 :     dst->shared_blks_written += add->shared_blks_written;
     232        2796 :     dst->local_blks_hit += add->local_blks_hit;
     233        2796 :     dst->local_blks_read += add->local_blks_read;
     234        2796 :     dst->local_blks_dirtied += add->local_blks_dirtied;
     235        2796 :     dst->local_blks_written += add->local_blks_written;
     236        2796 :     dst->temp_blks_read += add->temp_blks_read;
     237        2796 :     dst->temp_blks_written += add->temp_blks_written;
     238        2796 :     INSTR_TIME_ADD(dst->shared_blk_read_time, add->shared_blk_read_time);
     239        2796 :     INSTR_TIME_ADD(dst->shared_blk_write_time, add->shared_blk_write_time);
     240        2796 :     INSTR_TIME_ADD(dst->local_blk_read_time, add->local_blk_read_time);
     241        2796 :     INSTR_TIME_ADD(dst->local_blk_write_time, add->local_blk_write_time);
     242        2796 :     INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
     243        2796 :     INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
     244        2796 : }
     245             : 
     246             : /* dst += add - sub */
     247             : void
     248      442460 : BufferUsageAccumDiff(BufferUsage *dst,
     249             :                      const BufferUsage *add,
     250             :                      const BufferUsage *sub)
     251             : {
     252      442460 :     dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
     253      442460 :     dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
     254      442460 :     dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
     255      442460 :     dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
     256      442460 :     dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
     257      442460 :     dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
     258      442460 :     dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
     259      442460 :     dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
     260      442460 :     dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
     261      442460 :     dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
     262      442460 :     INSTR_TIME_ACCUM_DIFF(dst->shared_blk_read_time,
     263             :                           add->shared_blk_read_time, sub->shared_blk_read_time);
     264      442460 :     INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time,
     265             :                           add->shared_blk_write_time, sub->shared_blk_write_time);
     266      442460 :     INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time,
     267             :                           add->local_blk_read_time, sub->local_blk_read_time);
     268      442460 :     INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time,
     269             :                           add->local_blk_write_time, sub->local_blk_write_time);
     270      442460 :     INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
     271             :                           add->temp_blk_read_time, sub->temp_blk_read_time);
     272      442460 :     INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,
     273             :                           add->temp_blk_write_time, sub->temp_blk_write_time);
     274      442460 : }
     275             : 
     276             : /* helper functions for WAL usage accumulation */
     277             : static void
     278        2700 : WalUsageAdd(WalUsage *dst, WalUsage *add)
     279             : {
     280        2700 :     dst->wal_bytes += add->wal_bytes;
     281        2700 :     dst->wal_records += add->wal_records;
     282        2700 :     dst->wal_fpi += add->wal_fpi;
     283        2700 : }
     284             : 
     285             : void
     286      286352 : WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
     287             : {
     288      286352 :     dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
     289      286352 :     dst->wal_records += add->wal_records - sub->wal_records;
     290      286352 :     dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
     291      286352 : }

Generated by: LCOV version 1.14