contrib/auto_explain/auto_explain.c

   1 /*-------------------------------------------------------------------------
   2  *
   3  * auto_explain.c
   4  *
   5  *
   6  * Copyright (c) 2008-2025, 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 "utils/guc.h"
  22
  23 PG_MODULE_MAGIC;
  24
  25 /* GUC variables */
  26 static int      auto_explain_log_min_duration = -1; /* msec or -1 */
  27 static int      auto_explain_log_parameter_max_length = -1; /* bytes 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 */
  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 static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
  80 static void explain_ExecutorRun(QueryDesc *queryDesc,
  81                                                                 ScanDirection direction,
  82                                                                 uint64 count);
  83 static void explain_ExecutorFinish(QueryDesc *queryDesc);
  84 static void explain_ExecutorEnd(QueryDesc *queryDesc);
  85
  86
  87 /*
  88  * Module load callback
  89  */
  90 void
  91 _PG_init(void)
  92 {
  93         /* Define custom GUC variables. */
  94         DefineCustomIntVariable("auto_explain.log_min_duration",
  95                                                         "Sets the minimum execution time above which plans will be logged.",
  96                                                         "Zero prints all plans. -1 turns this feature off.",
  97                                                         &auto_explain_log_min_duration,
  98                                                         -1,
  99                                                         -1, INT_MAX,
 100                                                         PGC_SUSET,
 101                                                         GUC_UNIT_MS,
 102                                                         NULL,
 103                                                         NULL,
 104                                                         NULL);
 105
 106         DefineCustomIntVariable("auto_explain.log_parameter_max_length",
 107                                                         "Sets the maximum length of query parameters to log.",
 108                                                         "Zero logs no query parameters, -1 logs them in full.",
 109                                                         &auto_explain_log_parameter_max_length,
 110                                                         -1,
 111                                                         -1, INT_MAX,
 112                                                         PGC_SUSET,
 113                                                         GUC_UNIT_BYTE,
 114                                                         NULL,
 115                                                         NULL,
 116                                                         NULL);
 117
 118         DefineCustomBoolVariable("auto_explain.log_analyze",
 119                                                          "Use EXPLAIN ANALYZE for plan logging.",
 120                                                          NULL,
 121                                                          &auto_explain_log_analyze,
 122                                                          false,
 123                                                          PGC_SUSET,
 124                                                          0,
 125                                                          NULL,
 126                                                          NULL,
 127                                                          NULL);
 128
 129         DefineCustomBoolVariable("auto_explain.log_settings",
 130                                                          "Log modified configuration parameters affecting query planning.",
 131                                                          NULL,
 132                                                          &auto_explain_log_settings,
 133                                                          false,
 134                                                          PGC_SUSET,
 135                                                          0,
 136                                                          NULL,
 137                                                          NULL,
 138                                                          NULL);
 139
 140         DefineCustomBoolVariable("auto_explain.log_verbose",
 141                                                          "Use EXPLAIN VERBOSE for plan logging.",
 142                                                          NULL,
 143                                                          &auto_explain_log_verbose,
 144                                                          false,
 145                                                          PGC_SUSET,
 146                                                          0,
 147                                                          NULL,
 148                                                          NULL,
 149                                                          NULL);
 150
 151         DefineCustomBoolVariable("auto_explain.log_buffers",
 152                                                          "Log buffers usage.",
 153                                                          NULL,
 154                                                          &auto_explain_log_buffers,
 155                                                          false,
 156                                                          PGC_SUSET,
 157                                                          0,
 158                                                          NULL,
 159                                                          NULL,
 160                                                          NULL);
 161
 162         DefineCustomBoolVariable("auto_explain.log_wal",
 163                                                          "Log WAL usage.",
 164                                                          NULL,
 165                                                          &auto_explain_log_wal,
 166                                                          false,
 167                                                          PGC_SUSET,
 168                                                          0,
 169                                                          NULL,
 170                                                          NULL,
 171                                                          NULL);
 172
 173         DefineCustomBoolVariable("auto_explain.log_triggers",
 174                                                          "Include trigger statistics in plans.",
 175                                                          "This has no effect unless log_analyze is also set.",
 176                                                          &auto_explain_log_triggers,
 177                                                          false,
 178                                                          PGC_SUSET,
 179                                                          0,
 180                                                          NULL,
 181                                                          NULL,
 182                                                          NULL);
 183
 184         DefineCustomEnumVariable("auto_explain.log_format",
 185                                                          "EXPLAIN format to be used for plan logging.",
 186                                                          NULL,
 187                                                          &auto_explain_log_format,
 188                                                          EXPLAIN_FORMAT_TEXT,
 189                                                          format_options,
 190                                                          PGC_SUSET,
 191                                                          0,
 192                                                          NULL,
 193                                                          NULL,
 194                                                          NULL);
 195
 196         DefineCustomEnumVariable("auto_explain.log_level",
 197                                                          "Log level for the plan.",
 198                                                          NULL,
 199                                                          &auto_explain_log_level,
 200                                                          LOG,
 201                                                          loglevel_options,
 202                                                          PGC_SUSET,
 203                                                          0,
 204                                                          NULL,
 205                                                          NULL,
 206                                                          NULL);
 207
 208         DefineCustomBoolVariable("auto_explain.log_nested_statements",
 209                                                          "Log nested statements.",
 210                                                          NULL,
 211                                                          &auto_explain_log_nested_statements,
 212                                                          false,
 213                                                          PGC_SUSET,
 214                                                          0,
 215                                                          NULL,
 216                                                          NULL,
 217                                                          NULL);
 218
 219         DefineCustomBoolVariable("auto_explain.log_timing",
 220                                                          "Collect timing data, not just row counts.",
 221                                                          NULL,
 222                                                          &auto_explain_log_timing,
 223                                                          true,
 224                                                          PGC_SUSET,
 225                                                          0,
 226                                                          NULL,
 227                                                          NULL,
 228                                                          NULL);
 229
 230         DefineCustomRealVariable("auto_explain.sample_rate",
 231                                                          "Fraction of queries to process.",
 232                                                          NULL,
 233                                                          &auto_explain_sample_rate,
 234                                                          1.0,
 235                                                          0.0,
 236                                                          1.0,
 237                                                          PGC_SUSET,
 238                                                          0,
 239                                                          NULL,
 240                                                          NULL,
 241                                                          NULL);
 242
 243         MarkGUCPrefixReserved("auto_explain");
 244
 245         /* Install hooks. */
 246         prev_ExecutorStart = ExecutorStart_hook;
 247         ExecutorStart_hook = explain_ExecutorStart;
 248         prev_ExecutorRun = ExecutorRun_hook;
 249         ExecutorRun_hook = explain_ExecutorRun;
 250         prev_ExecutorFinish = ExecutorFinish_hook;
 251         ExecutorFinish_hook = explain_ExecutorFinish;
 252         prev_ExecutorEnd = ExecutorEnd_hook;
 253         ExecutorEnd_hook = explain_ExecutorEnd;
 254 }
 255
 256 /*
 257  * ExecutorStart hook: start up logging if needed
 258  */
 259 static void
 260 explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
 261 {
 262         /*
 263          * At the beginning of each top-level statement, decide whether we'll
 264          * sample this statement.  If nested-statement explaining is enabled,
 265          * either all nested statements will be explained or none will.
 266          *
 267          * When in a parallel worker, we should do nothing, which we can implement
 268          * cheaply by pretending we decided not to sample the current statement.
 269          * If EXPLAIN is active in the parent session, data will be collected and
 270          * reported back to the parent, and it's no business of ours to interfere.
 271          */
 272         if (nesting_level == 0)
 273         {
 274                 if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
 275                         current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
 276                 else
 277                         current_query_sampled = false;
 278         }
 279
 280         if (auto_explain_enabled())
 281         {
 282                 /* Enable per-node instrumentation iff log_analyze is required. */
 283                 if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
 284                 {
 285                         if (auto_explain_log_timing)
 286                                 queryDesc->instrument_options |= INSTRUMENT_TIMER;
 287                         else
 288                                 queryDesc->instrument_options |= INSTRUMENT_ROWS;
 289                         if (auto_explain_log_buffers)
 290                                 queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
 291                         if (auto_explain_log_wal)
 292                                 queryDesc->instrument_options |= INSTRUMENT_WAL;
 293                 }
 294         }
 295
 296         if (prev_ExecutorStart)
 297                 prev_ExecutorStart(queryDesc, eflags);
 298         else
 299                 standard_ExecutorStart(queryDesc, eflags);
 300
 301         if (auto_explain_enabled())
 302         {
 303                 /*
 304                  * Set up to track total elapsed time in ExecutorRun.  Make sure the
 305                  * space is allocated in the per-query context so it will go away at
 306                  * ExecutorEnd.
 307                  */
 308                 if (queryDesc->totaltime == NULL)
 309                 {
 310                         MemoryContext oldcxt;
 311
 312                         oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
 313                         queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
 314                         MemoryContextSwitchTo(oldcxt);
 315                 }
 316         }
 317 }
 318
 319 /*
 320  * ExecutorRun hook: all we need do is track nesting depth
 321  */
 322 static void
 323 explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
 324                                         uint64 count)
 325 {
 326         nesting_level++;
 327         PG_TRY();
 328         {
 329                 if (prev_ExecutorRun)
 330                         prev_ExecutorRun(queryDesc, direction, count);
 331                 else
 332                         standard_ExecutorRun(queryDesc, direction, count);
 333         }
 334         PG_FINALLY();
 335         {
 336                 nesting_level--;
 337         }
 338         PG_END_TRY();
 339 }
 340
 341 /*
 342  * ExecutorFinish hook: all we need do is track nesting depth
 343  */
 344 static void
 345 explain_ExecutorFinish(QueryDesc *queryDesc)
 346 {
 347         nesting_level++;
 348         PG_TRY();
 349         {
 350                 if (prev_ExecutorFinish)
 351                         prev_ExecutorFinish(queryDesc);
 352                 else
 353                         standard_ExecutorFinish(queryDesc);
 354         }
 355         PG_FINALLY();
 356         {
 357                 nesting_level--;
 358         }
 359         PG_END_TRY();
 360 }
 361
 362 /*
 363  * ExecutorEnd hook: log results if needed
 364  */
 365 static void
 366 explain_ExecutorEnd(QueryDesc *queryDesc)
 367 {
 368         if (queryDesc->totaltime && auto_explain_enabled())
 369         {
 370                 MemoryContext oldcxt;
 371                 double          msec;
 372
 373                 /*
 374                  * Make sure we operate in the per-query context, so any cruft will be
 375                  * discarded later during ExecutorEnd.
 376                  */
 377                 oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
 378
 379                 /*
 380                  * Make sure stats accumulation is done.  (Note: it's okay if several
 381                  * levels of hook all do this.)
 382                  */
 383                 InstrEndLoop(queryDesc->totaltime);
 384
 385                 /* Log plan if duration is exceeded. */
 386                 msec = queryDesc->totaltime->total * 1000.0;
 387                 if (msec >= auto_explain_log_min_duration)
 388                 {
 389                         ExplainState *es = NewExplainState();
 390
 391                         es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
 392                         es->verbose = auto_explain_log_verbose;
 393                         es->buffers = (es->analyze && auto_explain_log_buffers);
 394                         es->wal = (es->analyze && auto_explain_log_wal);
 395                         es->timing = (es->analyze && auto_explain_log_timing);
 396                         es->summary = es->analyze;
 397                         /* No support for MEMORY */
 398                         /* es->memory = false; */
 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 }