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

Generated by: LCOV version 1.14