From 02e732ad4cc031fead965c3af1b87822e73fe258 Mon Sep 17 00:00:00 2001 From: Tomas Vondra Date: Sat, 29 Oct 2022 22:01:01 +0200 Subject: [PATCH 05/11] wip: brinsort explain stats Show some internal stats about BRIN Sort in EXPLAIN output. --- src/backend/commands/explain.c | 132 ++++++++++++++++++++++++++++ src/backend/executor/nodeBrinSort.c | 66 +++++++++++--- src/include/nodes/execnodes.h | 39 ++++++++ 3 files changed, 223 insertions(+), 14 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 153e41b856f..1305083f1d3 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -87,6 +87,8 @@ static void show_incremental_sort_keys(IncrementalSortState *incrsortstate, List *ancestors, ExplainState *es); static void show_brinsort_keys(BrinSortState *sortstate, List *ancestors, ExplainState *es); +static void show_brinsort_stats(BrinSortState *sortstate, List *ancestors, + ExplainState *es); static void show_merge_append_keys(MergeAppendState *mstate, List *ancestors, ExplainState *es); static void show_agg_keys(AggState *astate, List *ancestors, @@ -1814,6 +1816,7 @@ ExplainNode(PlanState *planstate, List *ancestors, planstate, es); show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); show_brinsort_keys(castNode(BrinSortState, planstate), ancestors, es); + show_brinsort_stats(castNode(BrinSortState, planstate), ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, planstate, es); @@ -2432,6 +2435,135 @@ show_brinsort_keys(BrinSortState *sortstate, List *ancestors, ExplainState *es) ancestors, es); } +static void +show_brinsort_stats(BrinSortState *sortstate, List *ancestors, ExplainState *es) +{ + BrinSortStats *stats = &sortstate->bs_stats; + + if (sortstate->bs_scan != NULL && + sortstate->bs_scan->ranges != NULL) + { + TuplesortInstrumentation stats; + + memset(&stats, 0, sizeof(TuplesortInstrumentation)); + tuplesort_get_stats(sortstate->bs_scan->ranges, &stats); + + ExplainIndentText(es); + appendStringInfo(es->str, "Ranges: " INT64_FORMAT " Build time: " INT64_FORMAT " Method: %s Space: " INT64_FORMAT " kB (%s)\n", + sortstate->bs_scan->nranges, + sortstate->bs_stats.ranges_build_ms, + tuplesort_method_name(stats.sortMethod), + stats.spaceUsed, + tuplesort_space_type_name(stats.spaceType)); + } + + if (stats->sort_count > 0) + { + ExplainPropertyInteger("Ranges Processed", NULL, (int64) + stats->range_count, es); + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + ExplainPropertyInteger("Sorts", NULL, (int64) + stats->sort_count, es); + + ExplainIndentText(es); + appendStringInfo(es->str, "Tuples Sorted: " INT64_FORMAT " Per-sort: " INT64_FORMAT " Direct: " INT64_FORMAT " Spilled: " INT64_FORMAT " Respilled: " INT64_FORMAT "\n", + stats->ntuples_tuplesort_all, + stats->ntuples_tuplesort_all / stats->sort_count, + stats->ntuples_tuplesort_direct, + stats->ntuples_spilled, + stats->ntuples_respilled); + } + else + { + ExplainOpenGroup("Sorts", "Sorts", true, es); + + ExplainPropertyInteger("Count", NULL, (int64) + stats->sort_count, es); + + ExplainPropertyInteger("Tuples per sort", NULL, (int64) + stats->ntuples_tuplesort_all / stats->sort_count, es); + + ExplainPropertyInteger("Sorted tuples (all)", NULL, (int64) + stats->ntuples_tuplesort_all, es); + + ExplainPropertyInteger("Sorted tuples (direct)", NULL, (int64) + stats->ntuples_tuplesort_direct, es); + + ExplainPropertyInteger("Spilled tuples", NULL, (int64) + stats->ntuples_spilled, es); + + ExplainPropertyInteger("Respilled tuples", NULL, (int64) + stats->ntuples_respilled, es); + + ExplainCloseGroup("Sorts", "Sorts", true, es); + } + } + + if (stats->sort_count_in_memory > 0) + { + if (es->format == EXPLAIN_FORMAT_TEXT) + { + ExplainIndentText(es); + appendStringInfo(es->str, "Sorts (in-memory) Count: " INT64_FORMAT " Space Total: " INT64_FORMAT " kB Maximum: " INT64_FORMAT " kB Average: " INT64_FORMAT " kB\n", + stats->sort_count_in_memory, + stats->total_space_used_in_memory, + stats->max_space_used_in_memory, + stats->total_space_used_in_memory / stats->sort_count_in_memory); + } + else + { + ExplainOpenGroup("In-Memory Sorts", "In-Memory Sorts", true, es); + + ExplainPropertyInteger("Count", NULL, (int64) + stats->sort_count_in_memory, es); + + ExplainPropertyInteger("Average space", "kB", (int64) + stats->total_space_used_in_memory / stats->sort_count_in_memory, es); + + ExplainPropertyInteger("Maximum space", "kB", (int64) + stats->max_space_used_in_memory, es); + + ExplainPropertyInteger("Total space", "kB", (int64) + stats->total_space_used_in_memory, es); + + ExplainCloseGroup("In-Memory Sorts", "In-Memory Sorts", true, es); + } + } + + if (stats->sort_count_on_disk > 0) + { + if (es->format == EXPLAIN_FORMAT_TEXT) + { + ExplainIndentText(es); + appendStringInfo(es->str, "Sorts (on-disk) Count: " INT64_FORMAT " Space Total: " INT64_FORMAT " kB Maximum: " INT64_FORMAT " kB Average: " INT64_FORMAT " kB\n", + stats->sort_count_on_disk, + stats->total_space_used_on_disk, + stats->max_space_used_on_disk, + stats->total_space_used_on_disk / stats->sort_count_on_disk); + } + else + { + ExplainOpenGroup("On-Disk Sorts", "On-Disk Sorts", true, es); + + ExplainPropertyInteger("Count", NULL, (int64) + stats->sort_count_on_disk, es); + + ExplainPropertyInteger("Average space", "kB", (int64) + stats->total_space_used_on_disk / stats->sort_count_on_disk, es); + + ExplainPropertyInteger("Maximum space", "kB", (int64) + stats->max_space_used_on_disk, es); + + ExplainPropertyInteger("Total space", "kB", (int64) + stats->total_space_used_on_disk, es); + + ExplainCloseGroup("On-Disk Sorts", "On-Disk Sorts", true, es); + } + } +} + /* * Likewise, for a MergeAppend node. */ diff --git a/src/backend/executor/nodeBrinSort.c b/src/backend/executor/nodeBrinSort.c index 9505eafc548..614d28c83b1 100644 --- a/src/backend/executor/nodeBrinSort.c +++ b/src/backend/executor/nodeBrinSort.c @@ -450,6 +450,8 @@ brinsort_load_tuples(BrinSortState *node, bool check_watermark, bool null_proces if (null_processing && !(range->has_nulls || range->not_summarized || range->all_nulls)) return; + node->bs_stats.range_count++; + brinsort_start_tidscan(node); scan = node->ss.ss_currentScanDesc; @@ -534,7 +536,10 @@ brinsort_load_tuples(BrinSortState *node, bool check_watermark, bool null_proces /* Stash it to the tuplestore (when NULL, or ignore * it (when not-NULL). */ if (isnull) + { tuplestore_puttupleslot(node->bs_tuplestore, tmpslot); + node->bs_stats.ntuples_spilled++; + } /* NULL or not, we're done */ continue; @@ -554,7 +559,12 @@ brinsort_load_tuples(BrinSortState *node, bool check_watermark, bool null_proces &node->bs_sortsupport); if (cmp <= 0) + { tuplesort_puttupleslot(node->bs_tuplesortstate, tmpslot); + node->bs_stats.ntuples_tuplesort_direct++; + node->bs_stats.ntuples_tuplesort_all++; + node->bs_stats.ntuples_tuplesort++; + } else { /* @@ -565,6 +575,7 @@ brinsort_load_tuples(BrinSortState *node, bool check_watermark, bool null_proces * respill) and stop spilling. */ tuplestore_puttupleslot(node->bs_tuplestore, tmpslot); + node->bs_stats.ntuples_spilled++; } } @@ -633,7 +644,11 @@ brinsort_load_spill_tuples(BrinSortState *node, bool check_watermark) &node->bs_sortsupport); if (cmp <= 0) + { tuplesort_puttupleslot(node->bs_tuplesortstate, slot); + node->bs_stats.ntuples_tuplesort_all++; + node->bs_stats.ntuples_tuplesort++; + } else { /* @@ -644,6 +659,7 @@ brinsort_load_spill_tuples(BrinSortState *node, bool check_watermark) * respill) and stop spilling. */ tuplestore_puttupleslot(tupstore, slot); + node->bs_stats.ntuples_respilled++; } } @@ -933,23 +949,40 @@ IndexNext(BrinSortState *node) */ if (node->bs_tuplesortstate) { -#ifdef DEBUG_BRIN_SORT + TuplesortInstrumentation stats; + + /* + * Reset tuplesort statistics between runs, otherwise + * we'll keep re-using stats from the largest run. + */ tuplesort_reset_stats(node->bs_tuplesortstate); -#endif tuplesort_performsort(node->bs_tuplesortstate); -#ifdef DEBUG_BRIN_SORT - if (debug_brin_sort) - { - TuplesortInstrumentation stats; + node->bs_stats.sort_count++; + node->bs_stats.ntuples_tuplesort = 0; - memset(&stats, 0, sizeof(TuplesortInstrumentation)); - tuplesort_get_stats(node->bs_tuplesortstate, &stats); + tuplesort_get_stats(node->bs_tuplesortstate, &stats); - tuplesort_get_stats(node->bs_tuplesortstate, &stats); + if (stats.spaceType == SORT_SPACE_TYPE_DISK) + { + node->bs_stats.sort_count_on_disk++; + node->bs_stats.total_space_used_on_disk += stats.spaceUsed; + node->bs_stats.max_space_used_on_disk = Max(node->bs_stats.max_space_used_on_disk, + stats.spaceUsed); + } + else if (stats.spaceType == SORT_SPACE_TYPE_MEMORY) + { + node->bs_stats.sort_count_in_memory++; + node->bs_stats.total_space_used_in_memory += stats.spaceUsed; + node->bs_stats.max_space_used_in_memory = Max(node->bs_stats.max_space_used_in_memory, + stats.spaceUsed); + } - elog(WARNING, "method: %s space: %ld kB (%s)", +#ifdef DEBUG_BRIN_SORT + if (debug_brin_sort) + { + elog(WARNING, "method: %s space: " INT64_FORMAT " kB (%s)", tuplesort_method_name(stats.sortMethod), stats.spaceUsed, tuplesort_space_type_name(stats.spaceType)); @@ -1219,9 +1252,10 @@ ExecEndBrinSort(BrinSortState *node) tuplesort_end(node->bs_tuplesortstate); node->bs_tuplesortstate = NULL; - if (node->bs_scan->ranges != NULL) + if (node->bs_scan != NULL && + node->bs_scan->ranges != NULL) tuplesort_end(node->bs_scan->ranges); - node->bs_scan->ranges = NULL; + node->bs_scan = NULL; } /* ---------------------------------------------------------------- @@ -1311,6 +1345,7 @@ ExecInitBrinSortRanges(BrinSort *node, BrinSortState *planstate) FmgrInfo *rangeproc; BrinRangeScanDesc *brscan; bool asc; + TimestampTz start_ts; /* BRIN Sort only allows ORDER BY using a single column */ Assert(node->numCols == 1); @@ -1355,15 +1390,18 @@ ExecInitBrinSortRanges(BrinSort *node, BrinSortState *planstate) /* * Ask the opclass to produce ranges in appropriate ordering. - * - * XXX Pass info about ASC/DESC, NULLS FIRST/LAST. */ + start_ts = GetCurrentTimestamp(); + brscan = (BrinRangeScanDesc *) DatumGetPointer(FunctionCall3Coll(rangeproc, node->collations[0], PointerGetDatum(scan), Int16GetDatum(attno), BoolGetDatum(asc))); + planstate->bs_stats.ranges_build_ms + = TimestampDifferenceMilliseconds(start_ts, GetCurrentTimestamp()); + /* allocate for space, and also for the alternative ordering */ planstate->bs_scan = brscan; } diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index efe26938d0a..2a98286e11a 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -1628,6 +1628,44 @@ typedef struct BrinRanges BrinRange ranges[FLEXIBLE_ARRAY_MEMBER]; } BrinRanges; +typedef struct BrinSortStats +{ + /* number of sorts */ + int64 sort_count; + + /* number of ranges loaded */ + int64 range_count; + + /* tuples in the current tuplesort */ + int64 ntuples_tuplesort; + + /* tuples written directly to tuplesort */ + int64 ntuples_tuplesort_direct; + + /* tuples written to tuplesort (all) */ + int64 ntuples_tuplesort_all; + + /* tuples written to tuplestore */ + int64 ntuples_spilled; + + /* tuples copied from old to new tuplestore */ + int64 ntuples_respilled; + + /* number of in-memory/on-disk sorts */ + int64 sort_count_in_memory; + int64 sort_count_on_disk; + + /* total/maximum amount of space used by either sort */ + int64 total_space_used_in_memory; + int64 total_space_used_on_disk; + int64 max_space_used_in_memory; + int64 max_space_used_on_disk; + + /* time to build ranges (milliseconds) */ + int64 ranges_build_ms; + +} BrinSortStats; + typedef struct BrinSortState { ScanState ss; /* its first field is NodeTag */ @@ -1664,6 +1702,7 @@ typedef struct BrinSortState BrinSortPhase bs_phase; SortSupportData bs_sortsupport; ProjectionInfo *bs_ProjInfo; + BrinSortStats bs_stats; /* * We need two tuplesort instances - one for current range, one for -- 2.39.2