contrib/auto_explain/auto_explain.c

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