contrib/auto_explain/auto_explain.c

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