LCOV - code coverage report
Current view: top level - src/backend/executor - instrument.c (source / functions) Hit Total Coverage
Test: PostgreSQL 13beta1 Lines: 124 131 94.7 %
Date: 2020-06-05 19:06:29 Functions: 13 13 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-2020, 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        5088 : InstrAlloc(int n, int instrument_options)
      32             : {
      33             :     Instrumentation *instr;
      34             : 
      35             :     /* initialize all fields to zeroes, then modify as needed */
      36        5088 :     instr = palloc0(n * sizeof(Instrumentation));
      37        5088 :     if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL))
      38             :     {
      39        2588 :         bool        need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
      40        2588 :         bool        need_wal = (instrument_options & INSTRUMENT_WAL) != 0;
      41        2588 :         bool        need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
      42             :         int         i;
      43             : 
      44        5176 :         for (i = 0; i < n; i++)
      45             :         {
      46        2588 :             instr[i].need_bufusage = need_buffers;
      47        2588 :             instr[i].need_walusage = need_wal;
      48        2588 :             instr[i].need_timer = need_timer;
      49             :         }
      50             :     }
      51             : 
      52        5088 :     return instr;
      53             : }
      54             : 
      55             : /* Initialize a pre-allocated instrumentation structure. */
      56             : void
      57        1028 : InstrInit(Instrumentation *instr, int instrument_options)
      58             : {
      59        1028 :     memset(instr, 0, sizeof(Instrumentation));
      60        1028 :     instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
      61        1028 :     instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
      62        1028 :     instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
      63        1028 : }
      64             : 
      65             : /* Entry to a plan node */
      66             : void
      67     8272544 : InstrStartNode(Instrumentation *instr)
      68             : {
      69    14759076 :     if (instr->need_timer &&
      70     6486532 :         !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime))
      71           0 :         elog(ERROR, "InstrStartNode called twice in a row");
      72             : 
      73             :     /* save buffer usage totals at node entry, if needed */
      74     8272544 :     if (instr->need_bufusage)
      75      120592 :         instr->bufusage_start = pgBufferUsage;
      76             : 
      77     8272544 :     if (instr->need_walusage)
      78         392 :         instr->walusage_start = pgWalUsage;
      79     8272544 : }
      80             : 
      81             : /* Exit from a plan node */
      82             : void
      83     8272536 : InstrStopNode(Instrumentation *instr, double nTuples)
      84             : {
      85             :     instr_time  endtime;
      86             : 
      87             :     /* count the returned tuples */
      88     8272536 :     instr->tuplecount += nTuples;
      89             : 
      90             :     /* let's update the time only if the timer was requested */
      91     8272536 :     if (instr->need_timer)
      92             :     {
      93     6486532 :         if (INSTR_TIME_IS_ZERO(instr->starttime))
      94           0 :             elog(ERROR, "InstrStopNode called without start");
      95             : 
      96     6486532 :         INSTR_TIME_SET_CURRENT(endtime);
      97     6486742 :         INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
      98             : 
      99     6486532 :         INSTR_TIME_SET_ZERO(instr->starttime);
     100             :     }
     101             : 
     102             :     /* Add delta of buffer usage since entry to node's totals */
     103     8272536 :     if (instr->need_bufusage)
     104      120592 :         BufferUsageAccumDiff(&instr->bufusage,
     105      120592 :                              &pgBufferUsage, &instr->bufusage_start);
     106             : 
     107     8272536 :     if (instr->need_walusage)
     108         392 :         WalUsageAccumDiff(&instr->walusage,
     109         392 :                           &pgWalUsage, &instr->walusage_start);
     110             : 
     111             :     /* Is this the first tuple of this cycle? */
     112     8272536 :     if (!instr->running)
     113             :     {
     114        6456 :         instr->running = true;
     115        6456 :         instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
     116             :     }
     117     8272536 : }
     118             : 
     119             : /* Finish a run cycle for a plan node */
     120             : void
     121        7584 : InstrEndLoop(Instrumentation *instr)
     122             : {
     123             :     double      totaltime;
     124             : 
     125             :     /* Skip if nothing has happened, or already shut down */
     126        7584 :     if (!instr->running)
     127        1128 :         return;
     128             : 
     129        6456 :     if (!INSTR_TIME_IS_ZERO(instr->starttime))
     130           0 :         elog(ERROR, "InstrEndLoop called on running node");
     131             : 
     132             :     /* Accumulate per-cycle statistics into totals */
     133        6456 :     totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
     134             : 
     135        6456 :     instr->startup += instr->firsttuple;
     136        6456 :     instr->total += totaltime;
     137        6456 :     instr->ntuples += instr->tuplecount;
     138        6456 :     instr->nloops += 1;
     139             : 
     140             :     /* Reset for next cycle (if any) */
     141        6456 :     instr->running = false;
     142        6456 :     INSTR_TIME_SET_ZERO(instr->starttime);
     143        6456 :     INSTR_TIME_SET_ZERO(instr->counter);
     144        6456 :     instr->firsttuple = 0;
     145        6456 :     instr->tuplecount = 0;
     146             : }
     147             : 
     148             : /* aggregate instrumentation information */
     149             : void
     150        2520 : InstrAggNode(Instrumentation *dst, Instrumentation *add)
     151             : {
     152        2520 :     if (!dst->running && add->running)
     153             :     {
     154           0 :         dst->running = true;
     155           0 :         dst->firsttuple = add->firsttuple;
     156             :     }
     157        2520 :     else if (dst->running && add->running && dst->firsttuple > add->firsttuple)
     158           0 :         dst->firsttuple = add->firsttuple;
     159             : 
     160        2520 :     INSTR_TIME_ADD(dst->counter, add->counter);
     161             : 
     162        2520 :     dst->tuplecount += add->tuplecount;
     163        2520 :     dst->startup += add->startup;
     164        2520 :     dst->total += add->total;
     165        2520 :     dst->ntuples += add->ntuples;
     166        2520 :     dst->ntuples2 += add->ntuples2;
     167        2520 :     dst->nloops += add->nloops;
     168        2520 :     dst->nfiltered1 += add->nfiltered1;
     169        2520 :     dst->nfiltered2 += add->nfiltered2;
     170             : 
     171             :     /* Add delta of buffer usage since entry to node's totals */
     172        2520 :     if (dst->need_bufusage)
     173          64 :         BufferUsageAdd(&dst->bufusage, &add->bufusage);
     174             : 
     175        2520 :     if (dst->need_walusage)
     176           0 :         WalUsageAdd(&dst->walusage, &add->walusage);
     177        2520 : }
     178             : 
     179             : /* note current values during parallel executor startup */
     180             : void
     181        1570 : InstrStartParallelQuery(void)
     182             : {
     183        1570 :     save_pgBufferUsage = pgBufferUsage;
     184        1570 :     save_pgWalUsage = pgWalUsage;
     185        1570 : }
     186             : 
     187             : /* report usage after parallel executor shutdown */
     188             : void
     189        1566 : InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
     190             : {
     191        1566 :     memset(bufusage, 0, sizeof(BufferUsage));
     192        1566 :     BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage);
     193        1566 :     memset(walusage, 0, sizeof(WalUsage));
     194        1566 :     WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage);
     195        1566 : }
     196             : 
     197             : /* accumulate work done by workers in leader's stats */
     198             : void
     199        1566 : InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
     200             : {
     201        1566 :     BufferUsageAdd(&pgBufferUsage, bufusage);
     202        1566 :     WalUsageAdd(&pgWalUsage, walusage);
     203        1566 : }
     204             : 
     205             : /* dst += add */
     206             : static void
     207        1630 : BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
     208             : {
     209        1630 :     dst->shared_blks_hit += add->shared_blks_hit;
     210        1630 :     dst->shared_blks_read += add->shared_blks_read;
     211        1630 :     dst->shared_blks_dirtied += add->shared_blks_dirtied;
     212        1630 :     dst->shared_blks_written += add->shared_blks_written;
     213        1630 :     dst->local_blks_hit += add->local_blks_hit;
     214        1630 :     dst->local_blks_read += add->local_blks_read;
     215        1630 :     dst->local_blks_dirtied += add->local_blks_dirtied;
     216        1630 :     dst->local_blks_written += add->local_blks_written;
     217        1630 :     dst->temp_blks_read += add->temp_blks_read;
     218        1630 :     dst->temp_blks_written += add->temp_blks_written;
     219        1630 :     INSTR_TIME_ADD(dst->blk_read_time, add->blk_read_time);
     220        1630 :     INSTR_TIME_ADD(dst->blk_write_time, add->blk_write_time);
     221        1630 : }
     222             : 
     223             : /* dst += add - sub */
     224             : void
     225      122432 : BufferUsageAccumDiff(BufferUsage *dst,
     226             :                      const BufferUsage *add,
     227             :                      const BufferUsage *sub)
     228             : {
     229      122432 :     dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
     230      122432 :     dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
     231      122432 :     dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
     232      122432 :     dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
     233      122432 :     dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
     234      122432 :     dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
     235      122432 :     dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
     236      122432 :     dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
     237      122432 :     dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
     238      122432 :     dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
     239      122432 :     INSTR_TIME_ACCUM_DIFF(dst->blk_read_time,
     240             :                           add->blk_read_time, sub->blk_read_time);
     241      122432 :     INSTR_TIME_ACCUM_DIFF(dst->blk_write_time,
     242             :                           add->blk_write_time, sub->blk_write_time);
     243      122432 : }
     244             : 
     245             : /* helper functions for WAL usage accumulation */
     246             : static void
     247        1566 : WalUsageAdd(WalUsage *dst, WalUsage *add)
     248             : {
     249        1566 :     dst->wal_bytes += add->wal_bytes;
     250        1566 :     dst->wal_records += add->wal_records;
     251        1566 :     dst->wal_fpi += add->wal_fpi;
     252        1566 : }
     253             : 
     254             : void
     255        2346 : WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
     256             : {
     257        2346 :     dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
     258        2346 :     dst->wal_records += add->wal_records - sub->wal_records;
     259        2346 :     dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
     260        2346 : }

Generated by: LCOV version 1.13