LCOV - code coverage report
Current view: top level - contrib/auto_explain - auto_explain.c (source / functions) Hit Total Coverage
Test: PostgreSQL 14devel Lines: 0 106 0.0 %
Date: 2020-08-05 08:07:15 Functions: 0 7 0.0 %
Legend: Lines: hit not hit

          Line data    Source code
       1             : /*-------------------------------------------------------------------------
       2             :  *
       3             :  * auto_explain.c
       4             :  *
       5             :  *
       6             :  * Copyright (c) 2008-2020, PostgreSQL Global Development Group
       7             :  *
       8             :  * IDENTIFICATION
       9             :  *    contrib/auto_explain/auto_explain.c
      10             :  *
      11             :  *-------------------------------------------------------------------------
      12             :  */
      13             : #include "postgres.h"
      14             : 
      15             : #include <limits.h>
      16             : 
      17             : #include "access/parallel.h"
      18             : #include "commands/explain.h"
      19             : #include "executor/instrument.h"
      20             : #include "jit/jit.h"
      21             : #include "utils/guc.h"
      22             : 
      23           0 : PG_MODULE_MAGIC;
      24             : 
      25             : /* GUC variables */
      26             : static int  auto_explain_log_min_duration = -1; /* msec or -1 */
      27             : static bool auto_explain_log_analyze = false;
      28             : static bool auto_explain_log_verbose = false;
      29             : static bool auto_explain_log_buffers = false;
      30             : static bool auto_explain_log_wal = false;
      31             : static bool auto_explain_log_triggers = false;
      32             : static bool auto_explain_log_timing = true;
      33             : static bool auto_explain_log_settings = false;
      34             : static int  auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
      35             : static int  auto_explain_log_level = LOG;
      36             : static bool auto_explain_log_nested_statements = false;
      37             : static double auto_explain_sample_rate = 1;
      38             : 
      39             : static const struct config_enum_entry format_options[] = {
      40             :     {"text", EXPLAIN_FORMAT_TEXT, false},
      41             :     {"xml", EXPLAIN_FORMAT_XML, false},
      42             :     {"json", EXPLAIN_FORMAT_JSON, false},
      43             :     {"yaml", EXPLAIN_FORMAT_YAML, false},
      44             :     {NULL, 0, false}
      45             : };
      46             : 
      47             : static const struct config_enum_entry loglevel_options[] = {
      48             :     {"debug5", DEBUG5, false},
      49             :     {"debug4", DEBUG4, false},
      50             :     {"debug3", DEBUG3, false},
      51             :     {"debug2", DEBUG2, false},
      52             :     {"debug1", DEBUG1, false},
      53             :     {"debug", DEBUG2, true},
      54             :     {"info", INFO, false},
      55             :     {"notice", NOTICE, false},
      56             :     {"warning", WARNING, false},
      57             :     {"log", LOG, false},
      58             :     {NULL, 0, false}
      59             : };
      60             : 
      61             : /* Current nesting depth of ExecutorRun calls */
      62             : static int  nesting_level = 0;
      63             : 
      64             : /* Is the current top-level query to be sampled? */
      65             : static bool current_query_sampled = false;
      66             : 
      67             : #define auto_explain_enabled() \
      68             :     (auto_explain_log_min_duration >= 0 && \
      69             :      (nesting_level == 0 || auto_explain_log_nested_statements) && \
      70             :      current_query_sampled)
      71             : 
      72             : /* Saved hook values in case of unload */
      73             : static ExecutorStart_hook_type prev_ExecutorStart = NULL;
      74             : static ExecutorRun_hook_type prev_ExecutorRun = NULL;
      75             : static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
      76             : static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
      77             : 
      78             : void        _PG_init(void);
      79             : void        _PG_fini(void);
      80             : 
      81             : static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
      82             : static void explain_ExecutorRun(QueryDesc *queryDesc,
      83             :                                 ScanDirection direction,
      84             :                                 uint64 count, bool execute_once);
      85             : static void explain_ExecutorFinish(QueryDesc *queryDesc);
      86             : static void explain_ExecutorEnd(QueryDesc *queryDesc);
      87             : 
      88             : 
      89             : /*
      90             :  * Module load callback
      91             :  */
      92             : void
      93           0 : _PG_init(void)
      94             : {
      95             :     /* Define custom GUC variables. */
      96           0 :     DefineCustomIntVariable("auto_explain.log_min_duration",
      97             :                             "Sets the minimum execution time above which plans will be logged.",
      98             :                             "Zero prints all plans. -1 turns this feature off.",
      99             :                             &auto_explain_log_min_duration,
     100             :                             -1,
     101             :                             -1, INT_MAX,
     102             :                             PGC_SUSET,
     103             :                             GUC_UNIT_MS,
     104             :                             NULL,
     105             :                             NULL,
     106             :                             NULL);
     107             : 
     108           0 :     DefineCustomBoolVariable("auto_explain.log_analyze",
     109             :                              "Use EXPLAIN ANALYZE for plan logging.",
     110             :                              NULL,
     111             :                              &auto_explain_log_analyze,
     112             :                              false,
     113             :                              PGC_SUSET,
     114             :                              0,
     115             :                              NULL,
     116             :                              NULL,
     117             :                              NULL);
     118             : 
     119           0 :     DefineCustomBoolVariable("auto_explain.log_settings",
     120             :                              "Log modified configuration parameters affecting query planning.",
     121             :                              NULL,
     122             :                              &auto_explain_log_settings,
     123             :                              false,
     124             :                              PGC_SUSET,
     125             :                              0,
     126             :                              NULL,
     127             :                              NULL,
     128             :                              NULL);
     129             : 
     130           0 :     DefineCustomBoolVariable("auto_explain.log_verbose",
     131             :                              "Use EXPLAIN VERBOSE for plan logging.",
     132             :                              NULL,
     133             :                              &auto_explain_log_verbose,
     134             :                              false,
     135             :                              PGC_SUSET,
     136             :                              0,
     137             :                              NULL,
     138             :                              NULL,
     139             :                              NULL);
     140             : 
     141           0 :     DefineCustomBoolVariable("auto_explain.log_buffers",
     142             :                              "Log buffers usage.",
     143             :                              NULL,
     144             :                              &auto_explain_log_buffers,
     145             :                              false,
     146             :                              PGC_SUSET,
     147             :                              0,
     148             :                              NULL,
     149             :                              NULL,
     150             :                              NULL);
     151             : 
     152           0 :     DefineCustomBoolVariable("auto_explain.log_wal",
     153             :                              "Log WAL usage.",
     154             :                              NULL,
     155             :                              &auto_explain_log_wal,
     156             :                              false,
     157             :                              PGC_SUSET,
     158             :                              0,
     159             :                              NULL,
     160             :                              NULL,
     161             :                              NULL);
     162             : 
     163           0 :     DefineCustomBoolVariable("auto_explain.log_triggers",
     164             :                              "Include trigger statistics in plans.",
     165             :                              "This has no effect unless log_analyze is also set.",
     166             :                              &auto_explain_log_triggers,
     167             :                              false,
     168             :                              PGC_SUSET,
     169             :                              0,
     170             :                              NULL,
     171             :                              NULL,
     172             :                              NULL);
     173             : 
     174           0 :     DefineCustomEnumVariable("auto_explain.log_format",
     175             :                              "EXPLAIN format to be used for plan logging.",
     176             :                              NULL,
     177             :                              &auto_explain_log_format,
     178             :                              EXPLAIN_FORMAT_TEXT,
     179             :                              format_options,
     180             :                              PGC_SUSET,
     181             :                              0,
     182             :                              NULL,
     183             :                              NULL,
     184             :                              NULL);
     185             : 
     186           0 :     DefineCustomEnumVariable("auto_explain.log_level",
     187             :                              "Log level for the plan.",
     188             :                              NULL,
     189             :                              &auto_explain_log_level,
     190             :                              LOG,
     191             :                              loglevel_options,
     192             :                              PGC_SUSET,
     193             :                              0,
     194             :                              NULL,
     195             :                              NULL,
     196             :                              NULL);
     197             : 
     198           0 :     DefineCustomBoolVariable("auto_explain.log_nested_statements",
     199             :                              "Log nested statements.",
     200             :                              NULL,
     201             :                              &auto_explain_log_nested_statements,
     202             :                              false,
     203             :                              PGC_SUSET,
     204             :                              0,
     205             :                              NULL,
     206             :                              NULL,
     207             :                              NULL);
     208             : 
     209           0 :     DefineCustomBoolVariable("auto_explain.log_timing",
     210             :                              "Collect timing data, not just row counts.",
     211             :                              NULL,
     212             :                              &auto_explain_log_timing,
     213             :                              true,
     214             :                              PGC_SUSET,
     215             :                              0,
     216             :                              NULL,
     217             :                              NULL,
     218             :                              NULL);
     219             : 
     220           0 :     DefineCustomRealVariable("auto_explain.sample_rate",
     221             :                              "Fraction of queries to process.",
     222             :                              NULL,
     223             :                              &auto_explain_sample_rate,
     224             :                              1.0,
     225             :                              0.0,
     226             :                              1.0,
     227             :                              PGC_SUSET,
     228             :                              0,
     229             :                              NULL,
     230             :                              NULL,
     231             :                              NULL);
     232             : 
     233           0 :     EmitWarningsOnPlaceholders("auto_explain");
     234             : 
     235             :     /* Install hooks. */
     236           0 :     prev_ExecutorStart = ExecutorStart_hook;
     237           0 :     ExecutorStart_hook = explain_ExecutorStart;
     238           0 :     prev_ExecutorRun = ExecutorRun_hook;
     239           0 :     ExecutorRun_hook = explain_ExecutorRun;
     240           0 :     prev_ExecutorFinish = ExecutorFinish_hook;
     241           0 :     ExecutorFinish_hook = explain_ExecutorFinish;
     242           0 :     prev_ExecutorEnd = ExecutorEnd_hook;
     243           0 :     ExecutorEnd_hook = explain_ExecutorEnd;
     244           0 : }
     245             : 
     246             : /*
     247             :  * Module unload callback
     248             :  */
     249             : void
     250           0 : _PG_fini(void)
     251             : {
     252             :     /* Uninstall hooks. */
     253           0 :     ExecutorStart_hook = prev_ExecutorStart;
     254           0 :     ExecutorRun_hook = prev_ExecutorRun;
     255           0 :     ExecutorFinish_hook = prev_ExecutorFinish;
     256           0 :     ExecutorEnd_hook = prev_ExecutorEnd;
     257           0 : }
     258             : 
     259             : /*
     260             :  * ExecutorStart hook: start up logging if needed
     261             :  */
     262             : static void
     263           0 : explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
     264             : {
     265             :     /*
     266             :      * At the beginning of each top-level statement, decide whether we'll
     267             :      * sample this statement.  If nested-statement explaining is enabled,
     268             :      * either all nested statements will be explained or none will.
     269             :      *
     270             :      * When in a parallel worker, we should do nothing, which we can implement
     271             :      * cheaply by pretending we decided not to sample the current statement.
     272             :      * If EXPLAIN is active in the parent session, data will be collected and
     273             :      * reported back to the parent, and it's no business of ours to interfere.
     274             :      */
     275           0 :     if (nesting_level == 0)
     276             :     {
     277           0 :         if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
     278           0 :             current_query_sampled = (random() < auto_explain_sample_rate *
     279             :                                      ((double) MAX_RANDOM_VALUE + 1));
     280             :         else
     281           0 :             current_query_sampled = false;
     282             :     }
     283             : 
     284           0 :     if (auto_explain_enabled())
     285             :     {
     286             :         /* Enable per-node instrumentation iff log_analyze is required. */
     287           0 :         if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
     288             :         {
     289           0 :             if (auto_explain_log_timing)
     290           0 :                 queryDesc->instrument_options |= INSTRUMENT_TIMER;
     291             :             else
     292           0 :                 queryDesc->instrument_options |= INSTRUMENT_ROWS;
     293           0 :             if (auto_explain_log_buffers)
     294           0 :                 queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
     295           0 :             if (auto_explain_log_wal)
     296           0 :                 queryDesc->instrument_options |= INSTRUMENT_WAL;
     297             :         }
     298             :     }
     299             : 
     300           0 :     if (prev_ExecutorStart)
     301           0 :         prev_ExecutorStart(queryDesc, eflags);
     302             :     else
     303           0 :         standard_ExecutorStart(queryDesc, eflags);
     304             : 
     305           0 :     if (auto_explain_enabled())
     306             :     {
     307             :         /*
     308             :          * Set up to track total elapsed time in ExecutorRun.  Make sure the
     309             :          * space is allocated in the per-query context so it will go away at
     310             :          * ExecutorEnd.
     311             :          */
     312           0 :         if (queryDesc->totaltime == NULL)
     313             :         {
     314             :             MemoryContext oldcxt;
     315             : 
     316           0 :             oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
     317           0 :             queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
     318           0 :             MemoryContextSwitchTo(oldcxt);
     319             :         }
     320             :     }
     321           0 : }
     322             : 
     323             : /*
     324             :  * ExecutorRun hook: all we need do is track nesting depth
     325             :  */
     326             : static void
     327           0 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
     328             :                     uint64 count, bool execute_once)
     329             : {
     330           0 :     nesting_level++;
     331           0 :     PG_TRY();
     332             :     {
     333           0 :         if (prev_ExecutorRun)
     334           0 :             prev_ExecutorRun(queryDesc, direction, count, execute_once);
     335             :         else
     336           0 :             standard_ExecutorRun(queryDesc, direction, count, execute_once);
     337             :     }
     338           0 :     PG_FINALLY();
     339             :     {
     340           0 :         nesting_level--;
     341             :     }
     342           0 :     PG_END_TRY();
     343           0 : }
     344             : 
     345             : /*
     346             :  * ExecutorFinish hook: all we need do is track nesting depth
     347             :  */
     348             : static void
     349           0 : explain_ExecutorFinish(QueryDesc *queryDesc)
     350             : {
     351           0 :     nesting_level++;
     352           0 :     PG_TRY();
     353             :     {
     354           0 :         if (prev_ExecutorFinish)
     355           0 :             prev_ExecutorFinish(queryDesc);
     356             :         else
     357           0 :             standard_ExecutorFinish(queryDesc);
     358             :     }
     359           0 :     PG_FINALLY();
     360             :     {
     361           0 :         nesting_level--;
     362             :     }
     363           0 :     PG_END_TRY();
     364           0 : }
     365             : 
     366             : /*
     367             :  * ExecutorEnd hook: log results if needed
     368             :  */
     369             : static void
     370           0 : explain_ExecutorEnd(QueryDesc *queryDesc)
     371             : {
     372           0 :     if (queryDesc->totaltime && auto_explain_enabled())
     373             :     {
     374             :         double      msec;
     375             : 
     376             :         /*
     377             :          * Make sure stats accumulation is done.  (Note: it's okay if several
     378             :          * levels of hook all do this.)
     379             :          */
     380           0 :         InstrEndLoop(queryDesc->totaltime);
     381             : 
     382             :         /* Log plan if duration is exceeded. */
     383           0 :         msec = queryDesc->totaltime->total * 1000.0;
     384           0 :         if (msec >= auto_explain_log_min_duration)
     385             :         {
     386           0 :             ExplainState *es = NewExplainState();
     387             : 
     388           0 :             es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
     389           0 :             es->verbose = auto_explain_log_verbose;
     390           0 :             es->buffers = (es->analyze && auto_explain_log_buffers);
     391           0 :             es->wal = (es->analyze && auto_explain_log_wal);
     392           0 :             es->timing = (es->analyze && auto_explain_log_timing);
     393           0 :             es->summary = es->analyze;
     394           0 :             es->format = auto_explain_log_format;
     395           0 :             es->settings = auto_explain_log_settings;
     396             : 
     397           0 :             ExplainBeginOutput(es);
     398           0 :             ExplainQueryText(es, queryDesc);
     399           0 :             ExplainPrintPlan(es, queryDesc);
     400           0 :             if (es->analyze && auto_explain_log_triggers)
     401           0 :                 ExplainPrintTriggers(es, queryDesc);
     402           0 :             if (es->costs)
     403           0 :                 ExplainPrintJITSummary(es, queryDesc);
     404           0 :             ExplainEndOutput(es);
     405             : 
     406             :             /* Remove last line break */
     407           0 :             if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
     408           0 :                 es->str->data[--es->str->len] = '\0';
     409             : 
     410             :             /* Fix JSON to output an object */
     411           0 :             if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
     412             :             {
     413           0 :                 es->str->data[0] = '{';
     414           0 :                 es->str->data[es->str->len - 1] = '}';
     415             :             }
     416             : 
     417             :             /*
     418             :              * Note: we rely on the existing logging of context or
     419             :              * debug_query_string to identify just which statement is being
     420             :              * reported.  This isn't ideal but trying to do it here would
     421             :              * often result in duplication.
     422             :              */
     423           0 :             ereport(auto_explain_log_level,
     424             :                     (errmsg("duration: %.3f ms  plan:\n%s",
     425             :                             msec, es->str->data),
     426             :                      errhidestmt(true)));
     427             : 
     428           0 :             pfree(es->str->data);
     429             :         }
     430             :     }
     431             : 
     432           0 :     if (prev_ExecutorEnd)
     433           0 :         prev_ExecutorEnd(queryDesc);
     434             :     else
     435           0 :         standard_ExecutorEnd(queryDesc);
     436           0 : }

Generated by: LCOV version 1.13