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

Generated by: LCOV version 1.14