public inbox for [email protected]help / color / mirror / Atom feed
[PATCH 2/5] Optimize jsonb operator #>> using extracted JsonbValueAsText() 19+ messages / 6 participants [nested] [flat]
* [PATCH 2/5] Optimize jsonb operator #>> using extracted JsonbValueAsText() @ 2019-02-21 00:04 Nikita Glukhov <[email protected]> 0 siblings, 0 replies; 19+ messages in thread From: Nikita Glukhov @ 2019-02-21 00:04 UTC (permalink / raw) --- src/backend/utils/adt/jsonfuncs.c | 164 ++++++++++++-------------------------- 1 file changed, 50 insertions(+), 114 deletions(-) diff --git a/src/backend/utils/adt/jsonfuncs.c b/src/backend/utils/adt/jsonfuncs.c index dd88c09..162dffa 100644 --- a/src/backend/utils/adt/jsonfuncs.c +++ b/src/backend/utils/adt/jsonfuncs.c @@ -748,6 +748,47 @@ json_object_field_text(PG_FUNCTION_ARGS) PG_RETURN_NULL(); } +static text * +JsonbValueAsText(JsonbValue *v) +{ + switch (v->type) + { + case jbvNull: + return NULL; + + case jbvBool: + return v->val.boolean ? + cstring_to_text_with_len("true", 4) : + cstring_to_text_with_len("false", 5); + + case jbvString: + return cstring_to_text_with_len(v->val.string.val, + v->val.string.len); + + case jbvNumeric: + { + Datum cstr = DirectFunctionCall1(numeric_out, + PointerGetDatum(v->val.numeric)); + + return cstring_to_text(DatumGetCString(cstr)); + } + + case jbvBinary: + { + StringInfoData jtext; + + initStringInfo(&jtext); + (void) JsonbToCString(&jtext, v->val.binary.data, -1); + + return cstring_to_text_with_len(jtext.data, jtext.len); + } + + default: + elog(ERROR, "unrecognized jsonb type: %d", (int) v->type); + return NULL; + } +} + Datum jsonb_object_field_text(PG_FUNCTION_ARGS) { @@ -762,39 +803,9 @@ jsonb_object_field_text(PG_FUNCTION_ARGS) VARDATA_ANY(key), VARSIZE_ANY_EXHDR(key)); - if (v != NULL) - { - text *result = NULL; - - switch (v->type) - { - case jbvNull: - break; - case jbvBool: - result = cstring_to_text(v->val.boolean ? "true" : "false"); - break; - case jbvString: - result = cstring_to_text_with_len(v->val.string.val, v->val.string.len); - break; - case jbvNumeric: - result = cstring_to_text(DatumGetCString(DirectFunctionCall1(numeric_out, - PointerGetDatum(v->val.numeric)))); - break; - case jbvBinary: - { - StringInfo jtext = makeStringInfo(); - - (void) JsonbToCString(jtext, v->val.binary.data, -1); - result = cstring_to_text_with_len(jtext->data, jtext->len); - } - break; - default: - elog(ERROR, "unrecognized jsonb type: %d", (int) v->type); - } - if (result) - PG_RETURN_TEXT_P(result); - } + if (v != NULL && v->type != jbvNull) + PG_RETURN_TEXT_P(JsonbValueAsText(v)); PG_RETURN_NULL(); } @@ -879,39 +890,9 @@ jsonb_array_element_text(PG_FUNCTION_ARGS) } v = getIthJsonbValueFromContainer(&jb->root, element); - if (v != NULL) - { - text *result = NULL; - - switch (v->type) - { - case jbvNull: - break; - case jbvBool: - result = cstring_to_text(v->val.boolean ? "true" : "false"); - break; - case jbvString: - result = cstring_to_text_with_len(v->val.string.val, v->val.string.len); - break; - case jbvNumeric: - result = cstring_to_text(DatumGetCString(DirectFunctionCall1(numeric_out, - PointerGetDatum(v->val.numeric)))); - break; - case jbvBinary: - { - StringInfo jtext = makeStringInfo(); - - (void) JsonbToCString(jtext, v->val.binary.data, -1); - result = cstring_to_text_with_len(jtext->data, jtext->len); - } - break; - default: - elog(ERROR, "unrecognized jsonb type: %d", (int) v->type); - } - if (result) - PG_RETURN_TEXT_P(result); - } + if (v != NULL && v->type != jbvNull) + PG_RETURN_TEXT_P(JsonbValueAsText(v)); PG_RETURN_NULL(); } @@ -1389,7 +1370,6 @@ get_jsonb_path_all(FunctionCallInfo fcinfo, bool as_text) { Jsonb *jb = PG_GETARG_JSONB_P(0); ArrayType *path = PG_GETARG_ARRAYTYPE_P(1); - Jsonb *res; Datum *pathtext; bool *pathnulls; int npath; @@ -1397,7 +1377,6 @@ get_jsonb_path_all(FunctionCallInfo fcinfo, bool as_text) bool have_object = false, have_array = false; JsonbValue *jbvp = NULL; - JsonbValue tv; JsonbContainer *container; /* @@ -1526,24 +1505,15 @@ get_jsonb_path_all(FunctionCallInfo fcinfo, bool as_text) if (as_text) { - /* special-case outputs for string and null values */ - if (jbvp->type == jbvString) - PG_RETURN_TEXT_P(cstring_to_text_with_len(jbvp->val.string.val, - jbvp->val.string.len)); if (jbvp->type == jbvNull) PG_RETURN_NULL(); - } - res = JsonbValueToJsonb(jbvp); - - if (as_text) - { - PG_RETURN_TEXT_P(cstring_to_text(JsonbToCString(NULL, - &res->root, - VARSIZE(res)))); + PG_RETURN_TEXT_P(JsonbValueAsText(jbvp)); } else { + Jsonb *res = JsonbValueToJsonb(jbvp); + /* not text mode - just hand back the jsonb */ PG_RETURN_JSONB_P(res); } @@ -1760,24 +1730,7 @@ each_worker_jsonb(FunctionCallInfo fcinfo, const char *funcname, bool as_text) } else { - text *sv; - - if (v.type == jbvString) - { - /* In text mode, scalar strings should be dequoted */ - sv = cstring_to_text_with_len(v.val.string.val, v.val.string.len); - } - else - { - /* Turn anything else into a json string */ - StringInfo jtext = makeStringInfo(); - Jsonb *jb = JsonbValueToJsonb(&v); - - (void) JsonbToCString(jtext, &jb->root, 0); - sv = cstring_to_text_with_len(jtext->data, jtext->len); - } - - values[1] = PointerGetDatum(sv); + values[1] = PointerGetDatum(JsonbValueAsText(&v)); } } else @@ -2070,24 +2023,7 @@ elements_worker_jsonb(FunctionCallInfo fcinfo, const char *funcname, } else { - text *sv; - - if (v.type == jbvString) - { - /* in text mode scalar strings should be dequoted */ - sv = cstring_to_text_with_len(v.val.string.val, v.val.string.len); - } - else - { - /* turn anything else into a json string */ - StringInfo jtext = makeStringInfo(); - Jsonb *jb = JsonbValueToJsonb(&v); - - (void) JsonbToCString(jtext, &jb->root, 0); - sv = cstring_to_text_with_len(jtext->data, jtext->len); - } - - values[0] = PointerGetDatum(sv); + values[0] = PointerGetDatum(JsonbValueAsText(&v)); } } -- 2.7.4 --------------55D1241744B27FF04177252F Content-Type: text/x-patch; name="0003-Optimize-JsonbContainer-type-recognition-v01.patch" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="0003-Optimize-JsonbContainer-type-recognition-v01.patch" ^ permalink raw reply [nested|flat] 19+ messages in thread
* [PATCH v3 4/7] Row pattern recognition patch (executor). @ 2023-07-26 10:49 Tatsuo Ishii <[email protected]> 0 siblings, 0 replies; 19+ messages in thread From: Tatsuo Ishii @ 2023-07-26 10:49 UTC (permalink / raw) --- src/backend/executor/nodeWindowAgg.c | 701 ++++++++++++++++++++++++++- src/backend/utils/adt/windowfuncs.c | 38 +- src/include/catalog/pg_proc.dat | 6 + src/include/nodes/execnodes.h | 18 + src/include/windowapi.h | 8 + 5 files changed, 758 insertions(+), 13 deletions(-) diff --git a/src/backend/executor/nodeWindowAgg.c b/src/backend/executor/nodeWindowAgg.c index 310ac23e3a..0586bf57d6 100644 --- a/src/backend/executor/nodeWindowAgg.c +++ b/src/backend/executor/nodeWindowAgg.c @@ -36,6 +36,7 @@ #include "access/htup_details.h" #include "catalog/objectaccess.h" #include "catalog/pg_aggregate.h" +#include "catalog/pg_collation_d.h" #include "catalog/pg_proc.h" #include "executor/executor.h" #include "executor/nodeWindowAgg.h" @@ -48,6 +49,7 @@ #include "utils/acl.h" #include "utils/builtins.h" #include "utils/datum.h" +#include "utils/fmgroids.h" #include "utils/expandeddatum.h" #include "utils/lsyscache.h" #include "utils/memutils.h" @@ -159,6 +161,14 @@ typedef struct WindowStatePerAggData bool restart; /* need to restart this agg in this cycle? */ } WindowStatePerAggData; +/* + * Map between Var attno in a target list and the parsed attno. + */ +typedef struct AttnoMap { + List *attno; /* att number in target list (list of AttNumber) */ + List *attnosyn; /* parsed att number (list of AttNumber) */ +} AttnoMap; + static void initialize_windowaggregate(WindowAggState *winstate, WindowStatePerFunc perfuncstate, WindowStatePerAgg peraggstate); @@ -182,8 +192,9 @@ static void begin_partition(WindowAggState *winstate); static void spool_tuples(WindowAggState *winstate, int64 pos); static void release_partition(WindowAggState *winstate); -static int row_is_in_frame(WindowAggState *winstate, int64 pos, +static int row_is_in_frame(WindowAggState *winstate, int64 pos, TupleTableSlot *slot); + static void update_frameheadpos(WindowAggState *winstate); static void update_frametailpos(WindowAggState *winstate); static void update_grouptailpos(WindowAggState *winstate); @@ -195,9 +206,19 @@ static Datum GetAggInitVal(Datum textInitVal, Oid transtype); static bool are_peers(WindowAggState *winstate, TupleTableSlot *slot1, TupleTableSlot *slot2); -static bool window_gettupleslot(WindowObject winobj, int64 pos, - TupleTableSlot *slot); +static void attno_map(Node *node, AttnoMap *map); +static bool attno_map_walker(Node *node, void *context); +static int row_is_in_reduced_frame(WindowObject winobj, int64 pos); + +static int64 evaluate_pattern(WindowObject winobj, int64 current_pos, + char *vname, StringInfo encoded_str, bool *result); + +static bool get_slots(WindowObject winobj, int64 current_pos); + +static int search_str_set(char *pattern, StringInfo *str_set, int set_size); +static void search_str_set_recurse(char *pattern, StringInfo *str_set, int set_size, int set_index, + char *encoded_str, int *resultlen); /* * initialize_windowaggregate @@ -673,6 +694,9 @@ eval_windowaggregates(WindowAggState *winstate) WindowObject agg_winobj; TupleTableSlot *agg_row_slot; TupleTableSlot *temp_slot; + bool reduced_frame_set; + bool check_reduced_frame; + int num_rows_in_reduced_frame; numaggs = winstate->numaggs; if (numaggs == 0) @@ -790,6 +814,7 @@ eval_windowaggregates(WindowAggState *winstate) (winstate->frameOptions & FRAMEOPTION_EXCLUSION) || winstate->aggregatedupto <= winstate->frameheadpos) { + elog(DEBUG1, "peraggstate->restart is set"); peraggstate->restart = true; numaggs_restart++; } @@ -861,8 +886,10 @@ eval_windowaggregates(WindowAggState *winstate) * If we created a mark pointer for aggregates, keep it pushed up to frame * head, so that tuplestore can discard unnecessary rows. */ +#ifdef NOT_USED if (agg_winobj->markptr >= 0) WinSetMarkPosition(agg_winobj, winstate->frameheadpos); +#endif /* * Now restart the aggregates that require it. @@ -919,6 +946,10 @@ eval_windowaggregates(WindowAggState *winstate) ExecClearTuple(agg_row_slot); } + reduced_frame_set = false; + check_reduced_frame = false; + num_rows_in_reduced_frame = 0; + /* * Advance until we reach a row not in frame (or end of partition). * @@ -930,12 +961,18 @@ eval_windowaggregates(WindowAggState *winstate) { int ret; + elog(DEBUG1, "===== loop in frame starts: " INT64_FORMAT, winstate->aggregatedupto); + /* Fetch next row if we didn't already */ if (TupIsNull(agg_row_slot)) { if (!window_gettupleslot(agg_winobj, winstate->aggregatedupto, agg_row_slot)) + { + if (check_reduced_frame) + winstate->aggregatedupto--; break; /* must be end of partition */ + } } /* @@ -944,10 +981,47 @@ eval_windowaggregates(WindowAggState *winstate) */ ret = row_is_in_frame(winstate, winstate->aggregatedupto, agg_row_slot); if (ret < 0) + { + if (winstate->patternVariableList != NIL && check_reduced_frame) + winstate->aggregatedupto--; break; + } if (ret == 0) goto next_tuple; + if (winstate->patternVariableList != NIL) + { + if (!reduced_frame_set) + { + num_rows_in_reduced_frame = row_is_in_reduced_frame(winstate->agg_winobj, winstate->aggregatedupto); + reduced_frame_set = true; + elog(DEBUG1, "set num_rows_in_reduced_frame: %d pos: " INT64_FORMAT, + num_rows_in_reduced_frame, winstate->aggregatedupto); + + if (num_rows_in_reduced_frame <= 0) + break; + + else if (num_rows_in_reduced_frame > 0) + check_reduced_frame = true; + } + + if (check_reduced_frame) + { + elog(DEBUG1, "decrease num_rows_in_reduced_frame: %d pos: " INT64_FORMAT, + num_rows_in_reduced_frame, winstate->aggregatedupto); + num_rows_in_reduced_frame--; + if (num_rows_in_reduced_frame < 0) + { + /* + * No more rows remain in the reduced frame. Finish + * accumulating row into the aggregates. + */ + winstate->aggregatedupto--; + break; + } + } + } + /* Set tuple context for evaluation of aggregate arguments */ winstate->tmpcontext->ecxt_outertuple = agg_row_slot; @@ -976,6 +1050,8 @@ next_tuple: ExecClearTuple(agg_row_slot); } + elog(DEBUG1, "===== break loop in frame starts: " INT64_FORMAT, winstate->aggregatedupto); + /* The frame's end is not supposed to move backwards, ever */ Assert(aggregatedupto_nonrestarted <= winstate->aggregatedupto); @@ -2053,6 +2129,8 @@ ExecWindowAgg(PlanState *pstate) CHECK_FOR_INTERRUPTS(); + elog(DEBUG1, "ExecWindowAgg called. pos: " INT64_FORMAT , winstate->currentpos); + if (winstate->status == WINDOWAGG_DONE) return NULL; @@ -2388,6 +2466,12 @@ ExecInitWindowAgg(WindowAgg *node, EState *estate, int eflags) TupleDesc scanDesc; ListCell *l; + TargetEntry *te; + Expr *expr; + Var *var; + int nargs; + AttnoMap attnomap; + /* check for unsupported flags */ Assert(!(eflags & (EXEC_FLAG_BACKWARD | EXEC_FLAG_MARK))); @@ -2483,6 +2567,16 @@ ExecInitWindowAgg(WindowAgg *node, EState *estate, int eflags) winstate->temp_slot_2 = ExecInitExtraTupleSlot(estate, scanDesc, &TTSOpsMinimalTuple); + winstate->prev_slot = ExecInitExtraTupleSlot(estate, scanDesc, + &TTSOpsMinimalTuple); + + winstate->next_slot = ExecInitExtraTupleSlot(estate, scanDesc, + &TTSOpsMinimalTuple); + + winstate->null_slot = ExecInitExtraTupleSlot(estate, scanDesc, + &TTSOpsMinimalTuple); + winstate->null_slot = ExecStoreAllNullTuple(winstate->null_slot); + /* * create frame head and tail slots only if needed (must create slots in * exactly the same cases that update_frameheadpos and update_frametailpos @@ -2667,6 +2761,69 @@ ExecInitWindowAgg(WindowAgg *node, EState *estate, int eflags) winstate->inRangeAsc = node->inRangeAsc; winstate->inRangeNullsFirst = node->inRangeNullsFirst; + /* Set up SKIP TO type */ + winstate->rpSkipTo = node->rpSkipTo; + /* Set up row pattern recognition PATTERN clause */ + winstate->patternVariableList = node->patternVariable; + winstate->patternRegexpList = node->patternRegexp; + + /* Set up row pattern recognition DEFINE clause */ + + /* + * Collect mapping between varattno and varattnosyn in the targetlist. + * XXX: For now we only check RPR's argument. Eventually we have to + * recurse the targetlist to find out all mappings in Var nodes. + */ + attnomap.attno = NIL; + attnomap.attnosyn = NIL; + + foreach (l, node->plan.targetlist) + { + te = lfirst(l); + if (IsA(te->expr, WindowFunc)) + { + WindowFunc *func = (WindowFunc *)te->expr; + + /* sanity check */ + nargs = list_length(func->args); + if (nargs != 1) + continue; + + expr = (Expr *) lfirst(list_head(func->args)); + if (!IsA(expr, Var)) + continue; + + var = (Var *)expr; + elog(DEBUG1, "resname: %s varattno: %d varattnosyn: %d", + te->resname, var->varattno, var->varattnosyn); + attnomap.attno = lappend_int(attnomap.attno, var->varattno); + attnomap.attnosyn = lappend_int(attnomap.attnosyn, var->varattnosyn); + } + } + + winstate->defineVariableList = NIL; + winstate->defineClauseList = NIL; + if (node->defineClause != NIL) + { + foreach(l, node->defineClause) + { + char *name; + ExprState *exps; + + te = lfirst(l); + name = te->resname; + expr = te->expr; + + elog(DEBUG1, "defineVariable name: %s", name); + winstate->defineVariableList = lappend(winstate->defineVariableList, + makeString(pstrdup(name))); + /* tweak expr so that it referes to outer slot */ + attno_map((Node *)expr, &attnomap); + exps = ExecInitExpr(expr, (PlanState *) winstate); + winstate->defineClauseList = lappend(winstate->defineClauseList, exps); + } + } + winstate->all_first = true; winstate->partition_spooled = false; winstate->more_partitions = false; @@ -2674,6 +2831,77 @@ ExecInitWindowAgg(WindowAgg *node, EState *estate, int eflags) return winstate; } +/* + * Rewrite Var node's varattno to the varattno which is used in the target + * list using AttnoMap. We also rewrite varno so that it sees outer tuple + * (PREV) or inner tuple (NEXT). + */ +static void +attno_map(Node *node, AttnoMap *map) +{ + (void) expression_tree_walker(node, attno_map_walker, (void *) map); +} + +static bool +attno_map_walker(Node *node, void *context) +{ + FuncExpr *func; + int nargs; + Expr *expr; + Var *var; + AttnoMap *attnomap; + ListCell *lc1, *lc2; + + if (node == NULL) + return false; + + attnomap = (AttnoMap *) context; + + if (IsA(node, FuncExpr)) + { + func = (FuncExpr *)node; + + if (func->funcid == F_PREV || func->funcid == F_NEXT) + { + /* sanity check */ + nargs = list_length(func->args); + if (list_length(func->args) != 1) + elog(ERROR, "PREV/NEXT must have 1 argument but function %d has %d args", func->funcid, nargs); + + expr = (Expr *) lfirst(list_head(func->args)); + if (!IsA(expr, Var)) + elog(ERROR, "PREV/NEXT's arg is not Var"); /* XXX: is it possible that arg type is Const? */ + var = (Var *)expr; + + if (func->funcid == F_PREV) + var->varno = OUTER_VAR; + else + var->varno = INNER_VAR; + } + return expression_tree_walker(node, attno_map_walker, (void *) context); + } + else if (IsA(node, Var)) + { + var = (Var *)node; + + elog(DEBUG1, "original varno: %d varattno: %d", var->varno, var->varattno); + + forboth(lc1, attnomap->attno, lc2, attnomap->attnosyn) + { + int attno = lfirst_int(lc1); + int attnosyn = lfirst_int(lc2); + + elog(DEBUG1, "walker: varattno: %d varattnosyn: %d",attno, attnosyn); + if (var->varattno == attnosyn) + { + elog(DEBUG1, "loc: %d rewrite varattno from: %d to %d", var->location, attnosyn, attno); + var->varattno = attno; + } + } + } + return expression_tree_walker(node, attno_map_walker, (void *) context); +} + /* ----------------- * ExecEndWindowAgg * ----------------- @@ -2691,6 +2919,8 @@ ExecEndWindowAgg(WindowAggState *node) ExecClearTuple(node->agg_row_slot); ExecClearTuple(node->temp_slot_1); ExecClearTuple(node->temp_slot_2); + ExecClearTuple(node->prev_slot); + ExecClearTuple(node->next_slot); if (node->framehead_slot) ExecClearTuple(node->framehead_slot); if (node->frametail_slot) @@ -2740,6 +2970,8 @@ ExecReScanWindowAgg(WindowAggState *node) ExecClearTuple(node->agg_row_slot); ExecClearTuple(node->temp_slot_1); ExecClearTuple(node->temp_slot_2); + ExecClearTuple(node->prev_slot); + ExecClearTuple(node->next_slot); if (node->framehead_slot) ExecClearTuple(node->framehead_slot); if (node->frametail_slot) @@ -3080,7 +3312,7 @@ are_peers(WindowAggState *winstate, TupleTableSlot *slot1, * * Returns true if successful, false if no such row */ -static bool +bool window_gettupleslot(WindowObject winobj, int64 pos, TupleTableSlot *slot) { WindowAggState *winstate = winobj->winstate; @@ -3100,7 +3332,7 @@ window_gettupleslot(WindowObject winobj, int64 pos, TupleTableSlot *slot) return false; if (pos < winobj->markpos) - elog(ERROR, "cannot fetch row before WindowObject's mark position"); + elog(ERROR, "cannot fetch row: " INT64_FORMAT " before WindowObject's mark position: " INT64_FORMAT, pos, winobj->markpos ); oldcontext = MemoryContextSwitchTo(winstate->ss.ps.ps_ExprContext->ecxt_per_query_memory); @@ -3420,14 +3652,54 @@ WinGetFuncArgInFrame(WindowObject winobj, int argno, WindowAggState *winstate; ExprContext *econtext; TupleTableSlot *slot; - int64 abs_pos; - int64 mark_pos; Assert(WindowObjectIsValid(winobj)); winstate = winobj->winstate; econtext = winstate->ss.ps.ps_ExprContext; slot = winstate->temp_slot_1; + if (WinGetSlotInFrame(winobj, slot, + relpos, seektype, set_mark, + isnull, isout) == 0) + { + econtext->ecxt_outertuple = slot; + return ExecEvalExpr((ExprState *) list_nth(winobj->argstates, argno), + econtext, isnull); + } + + if (isout) + *isout = true; + *isnull = true; + return (Datum) 0; +} + +/* + * WinGetSlotInFrame + * slot: TupleTableSlot to store the result + * relpos: signed rowcount offset from the seek position + * seektype: WINDOW_SEEK_HEAD or WINDOW_SEEK_TAIL + * set_mark: If the row is found/in frame and set_mark is true, the mark is + * moved to the row as a side-effect. + * isnull: output argument, receives isnull status of result + * isout: output argument, set to indicate whether target row position + * is out of frame (can pass NULL if caller doesn't care about this) + * + * Returns 0 if we successfullt got the slot. false if out of frame. + * (also isout is set) + */ +int +WinGetSlotInFrame(WindowObject winobj, TupleTableSlot *slot, + int relpos, int seektype, bool set_mark, + bool *isnull, bool *isout) +{ + WindowAggState *winstate; + int64 abs_pos; + int64 mark_pos; + int num_reduced_frame; + + Assert(WindowObjectIsValid(winobj)); + winstate = winobj->winstate; + switch (seektype) { case WINDOW_SEEK_CURRENT: @@ -3494,6 +3766,12 @@ WinGetFuncArgInFrame(WindowObject winobj, int argno, winstate->frameOptions); break; } + num_reduced_frame = row_is_in_reduced_frame(winobj, winstate->frameheadpos); + if (num_reduced_frame < 0) + goto out_of_frame; + else if (num_reduced_frame > 0) + if (relpos >= num_reduced_frame) + goto out_of_frame; break; case WINDOW_SEEK_TAIL: /* rejecting relpos > 0 is easy and simplifies code below */ @@ -3565,6 +3843,12 @@ WinGetFuncArgInFrame(WindowObject winobj, int argno, mark_pos = 0; /* keep compiler quiet */ break; } + + num_reduced_frame = row_is_in_reduced_frame(winobj, winstate->frameheadpos + relpos); + if (num_reduced_frame < 0) + goto out_of_frame; + else if (num_reduced_frame > 0) + abs_pos = winstate->frameheadpos + relpos + num_reduced_frame - 1; break; default: elog(ERROR, "unrecognized window seek type: %d", seektype); @@ -3583,15 +3867,13 @@ WinGetFuncArgInFrame(WindowObject winobj, int argno, *isout = false; if (set_mark) WinSetMarkPosition(winobj, mark_pos); - econtext->ecxt_outertuple = slot; - return ExecEvalExpr((ExprState *) list_nth(winobj->argstates, argno), - econtext, isnull); + return 0; out_of_frame: if (isout) *isout = true; *isnull = true; - return (Datum) 0; + return -1; } /* @@ -3622,3 +3904,400 @@ WinGetFuncArgCurrent(WindowObject winobj, int argno, bool *isnull) return ExecEvalExpr((ExprState *) list_nth(winobj->argstates, argno), econtext, isnull); } + +WindowAggState * +WinGetAggState(WindowObject winobj) +{ + return winobj->winstate; +} + +/* + * row_is_in_reduced_frame + * Determine whether a row is in the current row's reduced window frame according + * to row pattern matching + * + * The row must has been already determined that it is in a full window frame + * and fetched it into slot. + * + * Returns: + * = 0, RPR is not defined. + * >0, if the row is the first in the reduced frame. Return the number of rows in the reduced frame. + * -1, if the row is unmatched row + * -2, if the row is in the reduced frame but needed to be skipped because of + * AFTER MATCH SKIP PAST LAST ROW + */ +static +int row_is_in_reduced_frame(WindowObject winobj, int64 pos) +{ + WindowAggState *winstate = winobj->winstate; + ListCell *lc1, *lc2; + bool expression_result; + int num_matched_rows; + int64 original_pos; + bool anymatch; + StringInfo encoded_str; + StringInfo pattern_str = makeStringInfo(); + + /* + * Array of pattern variables evaluted to true. + * Each character corresponds to pattern variable. + * Example: + * str_set[0] = "AB"; + * str_set[1] = "AC"; + * In this case at row 0 A and B are true, and A and C are true in row 1. + */ + #define ENCODED_STR_ARRAY_ALLOC_SIZE 128 + StringInfo *str_set = NULL; + int str_set_index; + int str_set_size; + + if (winstate->patternVariableList == NIL) + { + /* + * RPR is not defined. Assume that we are always in the the reduced + * window frame. + */ + return 0; + } + + /* save original pos */ + original_pos = pos; + + /* + * Check whether the row speicied by pos is in the reduced frame. The + * second and subsequent rows need to be recognized as "unmatched" rows if + * AFTER MATCH SKIP PAST LAST ROW is defined. + */ + if (winstate->rpSkipTo == ST_PAST_LAST_ROW && + pos > winstate->headpos_in_reduced_frame && + pos < (winstate->headpos_in_reduced_frame + winstate->num_rows_in_reduced_frame)) + return -2; + + /* + * Loop over until none of pattern matches or encounters end of frame. + */ + for (;;) + { + int64 result_pos = -1; + + /* + * Loop over each PATTERN variable. + */ + anymatch = false; + encoded_str = makeStringInfo(); + + forboth(lc1, winstate->patternVariableList, lc2, winstate->patternRegexpList) + { + char *vname = strVal(lfirst(lc1)); + char *quantifier = strVal(lfirst(lc2)); + + elog(DEBUG1, "pos: " INT64_FORMAT " pattern vname: %s quantifier: %s", pos, vname, quantifier); + + expression_result = false; + + /* evaluate row pattern against current row */ + result_pos = evaluate_pattern(winobj, pos, vname, encoded_str, &expression_result); + if (expression_result) + { + elog(DEBUG1, "expression result is true"); + anymatch = true; + } + + /* + * If out of frame, we are done. + */ + if (result_pos < 0) + break; + } + + if (!anymatch) + { + /* none of patterns matched. */ + break; + } + + /* build encoded string array */ + if (str_set == NULL) + { + str_set_index = 0; + str_set_size = ENCODED_STR_ARRAY_ALLOC_SIZE * sizeof(StringInfo); + str_set = palloc(str_set_size); + } + + str_set[str_set_index++] = encoded_str; + + elog(DEBUG1, "pos: " INT64_FORMAT " str_set_index: %d encoded_str: %s", pos, str_set_index, encoded_str->data); + + if (str_set_index >= str_set_size) + { + str_set_size *= 2; + str_set = repalloc(str_set, str_set_size); + } + + /* move to next row */ + pos++; + + if (result_pos < 0) + { + /* out of frame */ + break; + } + } + + if (str_set == NULL) + { + /* no matches found in the first row */ + return -1; + } + + elog(DEBUG1, "pos: " INT64_FORMAT " encoded_str: %s", pos, encoded_str->data); + + /* build regular expression */ + pattern_str = makeStringInfo(); + appendStringInfoChar(pattern_str, '^'); + forboth(lc1, winstate->patternVariableList, lc2, winstate->patternRegexpList) + { + char *vname = strVal(lfirst(lc1)); + char *quantifier = strVal(lfirst(lc2)); + + appendStringInfoChar(pattern_str, vname[0]); + if (quantifier[0]) + appendStringInfoChar(pattern_str, quantifier[0]); + elog(DEBUG1, "vname: %s quantifier: %s", vname, quantifier); + } + + elog(DEBUG1, "pos: " INT64_FORMAT " pattern: %s", pos, pattern_str->data); + + /* look for matching pattern variable sequence */ + num_matched_rows = search_str_set(pattern_str->data, str_set, str_set_index); + if (num_matched_rows <= 0) + return -1; + + /* + * We are at the first row in the reduced frame. Save the number of + * matched rows as the number of rows in the reduced frame. + */ + winstate->headpos_in_reduced_frame = original_pos; + winstate->num_rows_in_reduced_frame = num_matched_rows; + + return num_matched_rows; +} + +/* + * search set of encode_str. + * set_size: size of set_str array. + */ +static +int search_str_set(char *pattern, StringInfo *str_set, int set_size) +{ + char *encoded_str = palloc0(set_size+1); + int resultlen = 0; + + search_str_set_recurse(pattern, str_set, set_size, 0, encoded_str, &resultlen); + elog(DEBUG1, "search_str_set returns %d", resultlen); + return resultlen; +} + +static +void search_str_set_recurse(char *pattern, StringInfo *str_set, int set_size, int set_index, char *encoded_str, int *resultlen) +{ + char *p; + + if (set_index >= set_size) + { + Datum d; + text *res; + char *substr; + + /* + * We first perform pattern matching using regexp_instr, then call + * textregexsubstr to get matched substring to know how log the + * matched string is. That is the number of rows in the reduced window + * frame. The reason why we can't call textregexsubstr is, it error + * out if pattern is not match. + */ + if (DatumGetInt32(DirectFunctionCall2Coll(regexp_instr, DEFAULT_COLLATION_OID, + PointerGetDatum(cstring_to_text(encoded_str)), + PointerGetDatum(cstring_to_text(pattern)))) > 0) + { + d = DirectFunctionCall2Coll(textregexsubstr, + DEFAULT_COLLATION_OID, + PointerGetDatum(cstring_to_text(encoded_str)), + PointerGetDatum(cstring_to_text(pattern))); + if (d != 0) + { + int len; + + res = DatumGetTextPP(d); + substr = text_to_cstring(res); + len = strlen(substr); + if (len > *resultlen) + /* remember the longest match */ + *resultlen = len; + } + } + return; + } + + p = str_set[set_index]->data; + while (*p) + { + encoded_str[set_index] = *p; + p++; + search_str_set_recurse(pattern, str_set, set_size, set_index + 1, encoded_str, resultlen); + } +} + + +/* + * Evaluate expression associated with PATTERN variable vname. + * relpos is relative row position in a frame (starting from 0). + * "quantifier" is the quatifier part of the PATTERN regular expression. + * Currently only '+' is allowed. + * result is out paramater representing the expression evaluation result + * is true of false. + * Return values are: + * >=0: the last match absolute row position + * other wise out of frame. + */ +static +int64 evaluate_pattern(WindowObject winobj, int64 current_pos, + char *vname, StringInfo encoded_str, bool *result) +{ + WindowAggState *winstate = winobj->winstate; + ExprContext *econtext = winstate->ss.ps.ps_ExprContext; + ListCell *lc1, *lc2; + ExprState *pat; + Datum eval_result; + bool out_of_frame = false; + bool isnull; + + forboth (lc1, winstate->defineVariableList, lc2, winstate->defineClauseList) + { + char *name = strVal(lfirst(lc1)); + + if (strcmp(vname, name)) + continue; + + /* set expression to evaluate */ + pat = lfirst(lc2); + + /* get current, previous and next tuples */ + if (!get_slots(winobj, current_pos)) + { + out_of_frame = true; + } + else + { + /* evaluate the expression */ + eval_result = ExecEvalExpr(pat, econtext, &isnull); + if (isnull) + { + /* expression is NULL */ + elog(DEBUG1, "expression for %s is NULL at row: " INT64_FORMAT, vname, current_pos); + *result = false; + } + else + { + if (!DatumGetBool(eval_result)) + { + /* expression is false */ + elog(DEBUG1, "expression for %s is false at row: " INT64_FORMAT, vname, current_pos); + *result = false; + } + else + { + /* expression is true */ + elog(DEBUG1, "expression for %s is true at row: " INT64_FORMAT, vname, current_pos); + appendStringInfoChar(encoded_str, vname[0]); + *result = true; + } + } + break; + } + + if (out_of_frame) + { + *result = false; + return -1; + } + } + return current_pos; +} + +/* + * Get current, previous and next tuples. + * Returns false if current row is out of partition/full frame. + */ +static +bool get_slots(WindowObject winobj, int64 current_pos) +{ + WindowAggState *winstate = winobj->winstate; + TupleTableSlot *slot; + int ret; + ExprContext *econtext; + + econtext = winstate->ss.ps.ps_ExprContext; + + /* set up current row tuple slot */ + slot = winstate->temp_slot_1; + if (!window_gettupleslot(winobj, current_pos, slot)) + { + elog(DEBUG1, "current row is out of partition at:" INT64_FORMAT, current_pos); + return false; + + ret = row_is_in_frame(winstate, current_pos, slot); + if (ret <= 0) + { + elog(DEBUG1, "current row is out of frame at: " INT64_FORMAT, current_pos); + return false; + } + } + econtext->ecxt_scantuple = slot; + + /* for PREV */ + if (current_pos > 0) + { + slot = winstate->prev_slot; + if (!window_gettupleslot(winobj, current_pos - 1, slot)) + { + elog(DEBUG1, "previous row is out of partition at: " INT64_FORMAT, current_pos - 1); + econtext->ecxt_outertuple = winstate->null_slot; + } + else + { + ret = row_is_in_frame(winstate, current_pos - 1, slot); + if (ret <= 0) + { + elog(DEBUG1, "previous row is out of frame at: " INT64_FORMAT, current_pos - 1); + econtext->ecxt_outertuple = winstate->null_slot; + } + else + { + econtext->ecxt_outertuple = slot; + } + } + } + else + econtext->ecxt_outertuple = winstate->null_slot; + + /* for NEXT */ + slot = winstate->next_slot; + if (!window_gettupleslot(winobj, current_pos + 1, slot)) + { + elog(DEBUG1, "next row is out of partiton at: " INT64_FORMAT, current_pos + 1); + econtext->ecxt_innertuple = winstate->null_slot; + } + else + { + ret = row_is_in_frame(winstate, current_pos + 1, slot); + if (ret <= 0) + { + elog(DEBUG1, "next row is out of frame at: " INT64_FORMAT, current_pos + 1); + econtext->ecxt_innertuple = winstate->null_slot; + } + else + econtext->ecxt_innertuple = slot; + } + return true; +} diff --git a/src/backend/utils/adt/windowfuncs.c b/src/backend/utils/adt/windowfuncs.c index b87a624fb2..e4cab36ec9 100644 --- a/src/backend/utils/adt/windowfuncs.c +++ b/src/backend/utils/adt/windowfuncs.c @@ -13,6 +13,9 @@ */ #include "postgres.h" +#include "catalog/pg_collation_d.h" +#include "executor/executor.h" +#include "nodes/execnodes.h" #include "nodes/supportnodes.h" #include "utils/builtins.h" #include "windowapi.h" @@ -36,11 +39,19 @@ typedef struct int64 remainder; /* (total rows) % (bucket num) */ } ntile_context; +/* + * rpr process information. + * Used for AFTER MATCH SKIP PAST LAST ROW + */ +typedef struct SkipContext +{ + int64 pos; /* last row absolute position */ +} SkipContext; + static bool rank_up(WindowObject winobj); static Datum leadlag_common(FunctionCallInfo fcinfo, bool forward, bool withoffset, bool withdefault); - /* * utility routine for *_rank functions. */ @@ -673,7 +684,7 @@ window_last_value(PG_FUNCTION_ARGS) bool isnull; result = WinGetFuncArgInFrame(winobj, 0, - 0, WINDOW_SEEK_TAIL, true, + 0, WINDOW_SEEK_TAIL, false, &isnull, NULL); if (isnull) PG_RETURN_NULL(); @@ -713,3 +724,26 @@ window_nth_value(PG_FUNCTION_ARGS) PG_RETURN_DATUM(result); } + +/* + * prev + * Dummy function to invoke RPR's navigation operator "PREV". + * This is *not* a window function. + */ +Datum +window_prev(PG_FUNCTION_ARGS) +{ + PG_RETURN_DATUM(PG_GETARG_DATUM(0)); +} + +/* + * next + * Dummy function to invoke RPR's navigation operation "NEXT". + * This is *not* a window function. + */ +Datum +window_next(PG_FUNCTION_ARGS) +{ + PG_RETURN_DATUM(PG_GETARG_DATUM(0)); +} + diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 6996073989..fa100b2665 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -10397,6 +10397,12 @@ { oid => '3114', descr => 'fetch the Nth row value', proname => 'nth_value', prokind => 'w', prorettype => 'anyelement', proargtypes => 'anyelement int4', prosrc => 'window_nth_value' }, +{ oid => '6122', descr => 'previous value', + proname => 'prev', provolatile => 's', prorettype => 'anyelement', + proargtypes => 'anyelement', prosrc => 'window_prev' }, +{ oid => '6123', descr => 'next value', + proname => 'next', provolatile => 's', prorettype => 'anyelement', + proargtypes => 'anyelement', prosrc => 'window_next' }, # functions for range types { oid => '3832', descr => 'I/O', diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index cb714f4a19..4fd3bd1a93 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -2519,6 +2519,14 @@ typedef struct WindowAggState int64 groupheadpos; /* current row's peer group head position */ int64 grouptailpos; /* " " " " tail position (group end+1) */ + /* these fields are used in Row pattern recognition: */ + RPSkipTo rpSkipTo; /* Row Pattern Skip To type */ + List *patternVariableList; /* list of row pattern variables names (list of String) */ + List *patternRegexpList; /* list of row pattern regular expressions ('+' or ''. list of String) */ + List *defineVariableList; /* list of row pattern definition variables (list of String) */ + List *defineClauseList; /* expression for row pattern definition + * search conditions ExprState list */ + MemoryContext partcontext; /* context for partition-lifespan data */ MemoryContext aggcontext; /* shared context for aggregate working data */ MemoryContext curaggcontext; /* current aggregate's working data */ @@ -2555,6 +2563,16 @@ typedef struct WindowAggState TupleTableSlot *agg_row_slot; TupleTableSlot *temp_slot_1; TupleTableSlot *temp_slot_2; + + /* temporary slots for RPR */ + TupleTableSlot *prev_slot; /* PREV row navigation operator */ + TupleTableSlot *next_slot; /* NEXT row navigation operator */ + TupleTableSlot *null_slot; /* all NULL slot */ + + /* head of the reduced window frame */ + int64 headpos_in_reduced_frame; + /* number of rows in the reduced window frame */ + int64 num_rows_in_reduced_frame; } WindowAggState; /* ---------------- diff --git a/src/include/windowapi.h b/src/include/windowapi.h index b8c2c565d1..1e292648e9 100644 --- a/src/include/windowapi.h +++ b/src/include/windowapi.h @@ -58,7 +58,15 @@ extern Datum WinGetFuncArgInFrame(WindowObject winobj, int argno, int relpos, int seektype, bool set_mark, bool *isnull, bool *isout); +extern int WinGetSlotInFrame(WindowObject winobj, TupleTableSlot *slot, + int relpos, int seektype, bool set_mark, + bool *isnull, bool *isout); + extern Datum WinGetFuncArgCurrent(WindowObject winobj, int argno, bool *isnull); +extern WindowAggState *WinGetAggState(WindowObject winobj); + +extern bool window_gettupleslot(WindowObject winobj, int64 pos, TupleTableSlot *slot); + #endif /* WINDOWAPI_H */ -- 2.25.1 ----Next_Part(Wed_Jul_26_21_21_34_2023_317)-- Content-Type: Text/X-Patch; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="v3-0005-Row-pattern-recognition-patch-docs.patch" ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-10 15:09 Bertrand Drouvot <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Bertrand Drouvot @ 2025-01-10 15:09 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: pgsql-hackers Hi, On Thu, Jan 02, 2025 at 12:24:06PM -0600, Sami Imseih wrote: > Having the total (auto)vacuum elapsed time > along side the existing (auto)vaccum_count > allows a user to track the average time an > operating overtime and to find vacuum tuning > opportunities. > > The same can also be said for (auto)analyze. I think that makes sense to expose those metrics through SQL as you're proposing here. The more we expose through SQL the better I think. > attached a patch ( without doc changes) > that adds 4 new columns: Thanks! A few random comments: === 1 + endtime = GetCurrentTimestamp(); pgstat_report_vacuum(RelationGetRelid(rel), rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); + vacrel->missed_dead_tuples, + starttime, + endtime); pgstat_progress_end_command(); if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); What about keeping the endtime assignment after the pgstat_progress_end_command() call? I think that it makes more sense that way. === 2 pgstat_report_vacuum(RelationGetRelid(rel), rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); + vacrel->missed_dead_tuples, + starttime, + endtime); What about doing the elapsedtime computation prior the this call and passed it as a parameter (then remove the starttime one and keep the endtime as it is needed)? === 3 pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), starttime, endtime); Same as 2 for pgstat_report_analyze() except that the endtime could be removed too. === 4 +/* pg_stat_get_vacuum_time */ +PG_STAT_GET_RELENTRY_INT64(total_vacuum_time) + +/* pg_stat_get_autovacuum_time */ +PG_STAT_GET_RELENTRY_INT64(total_autovacuum_time) + +/* pg_stat_get_analyze_time */ +PG_STAT_GET_RELENTRY_INT64(total_analyze_time) + +/* pg_stat_get_autoanalyze_time */ +PG_STAT_GET_RELENTRY_INT64(total_autoanalyze_time) I wonder if it wouldn't be better to use FLOAT8 here (to match things like pg_stat_get_checkpointer_write_time(), pg_stat_get_checkpointer_sync_time() among others). === 5 + + PgStat_Counter total_vacuum_time; /* user initiated vacuum */ + PgStat_Counter total_autovacuum_time; /* autovacuum initiated */ + PgStat_Counter total_analyze_time; /* user initiated vacuum */ + PgStat_Counter total_autoanalyze_time; /* autovacuum initiated */ Those comments look weird to me. Regards, -- Bertrand Drouvot PostgreSQL Contributors Team RDS Open Source Databases Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-10 22:26 Sami Imseih <[email protected]> parent: Bertrand Drouvot <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-10 22:26 UTC (permalink / raw) To: Bertrand Drouvot <[email protected]>; +Cc: pgsql-hackers Thanks for the review! > === 1 > > + endtime = GetCurrentTimestamp(); > pgstat_report_vacuum(RelationGetRelid(rel), > rel->rd_rel->relisshared, > Max(vacrel->new_live_tuples, 0), > vacrel->recently_dead_tuples + > - vacrel->missed_dead_tuples); > + vacrel->missed_dead_tuples, > + starttime, > + endtime); > pgstat_progress_end_command(); > > if (instrument) > { > - TimestampTz endtime = GetCurrentTimestamp(); > > What about keeping the endtime assignment after the pgstat_progress_end_command() > call? I think that it makes more sense that way. Yes, that can be done. I see a few more examples in which we report stats after end_command, i.e. AbortTransaction > What about doing the elapsedtime computation prior the this call and passed > it as a parameter (then remove the starttime one and keep the endtime as it > is needed)? Yes, makes sense. It will keep the changes to pgstat_report_ to a minimum. > === 4 > > +/* pg_stat_get_vacuum_time */ > +PG_STAT_GET_RELENTRY_INT64(total_vacuum_time) > + > +/* pg_stat_get_autovacuum_time */ > +PG_STAT_GET_RELENTRY_INT64(total_autovacuum_time) > + > +/* pg_stat_get_analyze_time */ > +PG_STAT_GET_RELENTRY_INT64(total_analyze_time) > + > +/* pg_stat_get_autoanalyze_time */ > +PG_STAT_GET_RELENTRY_INT64(total_autoanalyze_time) > > I wonder if it wouldn't be better to use FLOAT8 here (to match things like > pg_stat_get_checkpointer_write_time(), pg_stat_get_checkpointer_sync_time() among > others). > > === 5 I see the checkpointer write_time for example is converted to double "for presentation". I am not sure why, expect for maybe historical reasons. I will do the same for this new cumulative time field for the sake of consistency. There is no macro for relentry to return a stat as FLOAT8, so adding it as part of this patch. Datum pg_stat_get_checkpointer_write_time(PG_FUNCTION_ARGS) { /* time is already in msec, just convert to double for presentation */ PG_RETURN_FLOAT8((double) pgstat_fetch_stat_checkpointer()->write_time); } > + > + PgStat_Counter total_vacuum_time; /* user initiated vacuum */ > + PgStat_Counter total_autovacuum_time; /* autovacuum initiated */ > + PgStat_Counter total_analyze_time; /* user initiated vacuum */ > + PgStat_Counter total_autoanalyze_time; /* autovacuum initiated */ > > Those comments look weird to me. > Ok, Will remove these. I also updated the comments for the instrument code path to reflect the fact starttime is now set for all cases.Also, added documentation. See the attached v2. Regards, Sami Attachments: [application/octet-stream] v2-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch (16.4K, ../../CAA5RZ0tP6my7Mbr_syP7hRAiFANC_bG8SyoQF=-vfV9VawpV=g@mail.gmail.com/2-v2-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch) download | inline diff: From 243b0b45df15bb496c18928aceae36a8b6b71768 Mon Sep 17 00:00:00 2001 From: Sami Imseih <[email protected]> Date: Fri, 10 Jan 2025 16:13:09 -0600 Subject: [PATCH v2 1/1] Track per relation cumulative time spent in vacuum or analyze Added cumulative counter fields in pg_stat_all_tables for (auto)vacuum and (auto)analyze. This will allow a user to derive the average time spent for these operations with the help of the exiting (auto)vacuum_count and (auto)analyze_count fields. --- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ src/backend/access/heap/vacuumlazy.c | 22 +++++++++--- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 18 ++++++---- src/backend/utils/activity/pgstat_relation.c | 23 +++++++----- src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/test/regress/expected/rules.out | 18 ++++++++-- 9 files changed, 153 insertions(+), 26 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index d0d176cc54..0957a49f74 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4040,6 +4040,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in manual vacuum + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in vacuum by the autovacuum + daemon + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in manual analyze + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in analyze by the autovacuum + daemon + </para></entry> + </row> </tbody> </tgroup> </table> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 09fab08b8e..6ecd10e427 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -319,6 +319,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allvisible; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; WalUsage startwalusage = pgWalUsage; @@ -329,10 +331,14 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, verbose = (params->options & VACOPT_VERBOSE) != 0; instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)); + + /* + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. + */ if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -343,6 +349,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); + starttime = GetCurrentTimestamp(); + /* * Setup error traceback support for ereport() first. The idea is to set * up an error context callback to display additional information on any @@ -591,6 +599,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->NewRelfrozenXid, vacrel->NewRelminMxid, &frozenxid_updated, &minmulti_updated, false); + pgstat_progress_end_command(); + + endtime = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime); + /* * Report results to the cumulative stats system, too. * @@ -605,13 +618,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); - pgstat_progress_end_command(); + vacrel->missed_dead_tuples, + endtime, + elapsedtime); if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 7a595c84db..cf35bff30b 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -691,7 +691,11 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_vacuum_count(C.oid) AS vacuum_count, pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count, pg_stat_get_analyze_count(C.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 2a7769b1fd..768e1b509e 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -299,6 +299,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, HeapTuple *rows; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; MemoryContext caller_context; Oid save_userid; int save_sec_context; @@ -344,8 +346,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +358,10 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -682,6 +685,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, in_outer_xact); } + elapsedtime = TimestampDifferenceMilliseconds(starttime, + GetCurrentTimestamp()); + /* * Now report ANALYZE to the cumulative stats system. For regular tables, * we do it only if not doing inherited stats. For partitioned tables, we @@ -693,9 +699,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), elapsedtime); else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) - pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL)); + pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), elapsedtime); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. @@ -732,8 +738,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* Log the action if appropriate */ if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 09247ba097..6a2033524a 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,20 +208,17 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples) + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); - TimestampTz ts; if (!pgstat_track_counts) return; - /* Store the data in the table's hash table entry. */ - ts = GetCurrentTimestamp(); - /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, tableoid, false); @@ -246,15 +243,20 @@ pgstat_report_vacuum(Oid tableoid, bool shared, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autovacuum_time = ts; + tabentry->last_autovacuum_time = endtime; tabentry->autovacuum_count++; } else { - tabentry->last_vacuum_time = ts; + tabentry->last_vacuum_time = endtime; tabentry->vacuum_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autovacuum_time += elapsedtime; + else + tabentry->total_vacuum_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* @@ -276,7 +278,7 @@ pgstat_report_vacuum(Oid tableoid, bool shared, void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter) + bool resetcounter, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; @@ -347,6 +349,11 @@ pgstat_report_analyze(Relation rel, tabentry->analyze_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autoanalyze_time += elapsedtime; + else + tabentry->total_analyze_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* see pgstat_report_vacuum() */ diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 5f8d20a406..81ced7cde4 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -52,6 +52,22 @@ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ PG_RETURN_INT64(result); \ } +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + int64 result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (float8) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + /* pg_stat_get_analyze_count */ PG_STAT_GET_RELENTRY_INT64(analyze_count) @@ -106,6 +122,18 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +/* pg_stat_get_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index b37e8a6f88..4ca8430b67 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5540,6 +5540,22 @@ proname => 'pg_stat_get_autoanalyze_count', provolatile => 's', proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', prosrc => 'pg_stat_get_autoanalyze_count' }, +{ oid => '8406', descr => 'total vacuum time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_time' }, +{ oid => '8407', descr => 'total autovacuum time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_time' }, +{ oid => '8408', descr => 'total analyze time, in milliseconds', + proname => 'pg_stat_get_total_analyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_analyze_time' }, +{ oid => '8409', descr => 'total autoanalyze time, in milliseconds', + proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autoanalyze_time' }, { oid => '1936', descr => 'statistics: currently active backend IDs', proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't', provolatile => 's', proparallel => 'r', prorettype => 'int4', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 6475889c58..5ce2d5d718 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -502,6 +502,11 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -676,10 +681,11 @@ extern void pgstat_assoc_relation(Relation rel); extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples); + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, PgStat_Counter elapsedtime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 3014d047fe..33f631dafa 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) @@ -2188,7 +2192,11 @@ pg_stat_sys_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); pg_stat_user_functions| SELECT p.oid AS funcid, @@ -2236,7 +2244,11 @@ pg_stat_user_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); pg_stat_wal| SELECT wal_records, -- 2.39.5 (Apple Git-154) ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-13 15:55 Bertrand Drouvot <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Bertrand Drouvot @ 2025-01-13 15:55 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: pgsql-hackers Hi, On Fri, Jan 10, 2025 at 04:26:05PM -0600, Sami Imseih wrote: > { > /* time is already in msec, just convert to double for presentation */ > PG_RETURN_FLOAT8((double) > pgstat_fetch_stat_checkpointer()->write_time); > } > > > + > > + PgStat_Counter total_vacuum_time; /* user initiated vacuum */ > > + PgStat_Counter total_autovacuum_time; /* autovacuum initiated */ > > + PgStat_Counter total_analyze_time; /* user initiated vacuum */ > > + PgStat_Counter total_autoanalyze_time; /* autovacuum initiated */ > > > > Those comments look weird to me. > > > > Ok, Will remove these. > > I also updated the comments for the instrument code path to reflect the > fact starttime is now set for all cases.Also, added documentation. > > See the attached v2. Thanks for the patch update! A few random comments: === 1 +/* pg_stat_get_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + The comments do not reflect the function names ("total" is missing to give pg_stat_get_total_vacuum_time() and such). === 2 +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) +Datum +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) +{ + Oid relid = PG_GETARG_OID(0); + int64 result; + PgStat_StatTabEntry *tabentry; + + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) + result = 0; + else + result = (float8) (tabentry->stat); + + PG_RETURN_FLOAT8(result); +} + /* pg_stat_get_analyze_count */ PG_STAT_GET_RELENTRY_INT64(analyze_count I think it's better to define the macro just before its first usage (meaning just after pg_stat_get_vacuum_count()): that would be consistent with the places the other macros are defined. === 3 + int64 result; s/int64/double/? === 4 + Total time this table has spent in manual vacuum + </para></entry> Mention the unit? === 5 + /* + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. + */ if (instrument) { Out of curiosity, why this extra comment? To be somehow consistent with do_analyze_rel()? === 6 @@ -343,6 +349,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); + starttime = GetCurrentTimestamp(); I wonder if it wouldn't make more sense to put the GetCurrentTimestamp() call before the pgstat_progress_start_command() call. That would be aligned with the "endtime" being after the pgstat_progress_end_command() and where it was before the patch. Regards, -- Bertrand Drouvot PostgreSQL Contributors Team RDS Open Source Databases Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-14 23:01 Sami Imseih <[email protected]> parent: Bertrand Drouvot <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-14 23:01 UTC (permalink / raw) To: Bertrand Drouvot <[email protected]>; +Cc: pgsql-hackers thanks for the review! > The comments do not reflect the function names ("total" is missing to give > pg_stat_get_total_vacuum_time() and such). fixed > I think it's better to define the macro just before its first usage (meaning > just after pg_stat_get_vacuum_count()): that would be consistent with the places > the other macros are defined. correct. I fixed this to match the placement of similar macros. > s/int64/double/? fixed > Mention the unit? fixed > Out of curiosity, why this extra comment? To be somehow consistent with > do_analyze_rel()? Yes, I added it for consistency, but since the comment was not there before, I just decided to remove it. > I wonder if it wouldn't make more sense to put the GetCurrentTimestamp() call > before the pgstat_progress_start_command() call. That would be aligned with the > "endtime" being after the pgstat_progress_end_command() and where it was before > the patch. I agree. Fixed. Please see the attached v3. Regards, Sami Attachments: [application/octet-stream] v3-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch (16.0K, ../../CAA5RZ0v9060p7hjtLPY9i0Me6SoaRKYwxATqt_DnZr8dGSnUhQ@mail.gmail.com/2-v3-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch) download | inline diff: From 69b2b23face81daa4ef3870988c9a0e51140321b Mon Sep 17 00:00:00 2001 From: EC2 Default User <[email protected]> Date: Mon, 13 Jan 2025 17:27:40 +0000 Subject: [PATCH v3 1/1] Track per relation cumulative time spent in vacuum or analyze Added cumulative counter fields in pg_stat_all_tables for (auto)vacuum and (auto)analyze. This will allow a user to derive the average time spent for these operations with the help of the exiting (auto)vacuum_count and (auto)analyze_count fields. --- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ src/backend/access/heap/vacuumlazy.c | 18 +++++++--- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 18 ++++++---- src/backend/utils/activity/pgstat_relation.c | 23 +++++++----- src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/test/regress/expected/rules.out | 18 ++++++++-- 9 files changed, 149 insertions(+), 26 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index d0d176cc54..909c6eb535 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4040,6 +4040,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in manual vacuum, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in vacuum by the autovacuum + daemon, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in manual analyze, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>bigint</type> + </para> + <para> + Total time this table has spent in analyze by the autovacuum + daemon, in milliseconds + </para></entry> + </row> </tbody> </tgroup> </table> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 09fab08b8e..432359e548 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -319,6 +319,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allvisible; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; WalUsage startwalusage = pgWalUsage; @@ -329,10 +331,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, verbose = (params->options & VACOPT_VERBOSE) != 0; instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)); + if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -340,6 +342,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } + starttime = GetCurrentTimestamp(); + pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -591,6 +595,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->NewRelfrozenXid, vacrel->NewRelminMxid, &frozenxid_updated, &minmulti_updated, false); + pgstat_progress_end_command(); + + endtime = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime); + /* * Report results to the cumulative stats system, too. * @@ -605,13 +614,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); - pgstat_progress_end_command(); + vacrel->missed_dead_tuples, + endtime, + elapsedtime); if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 7a595c84db..cf35bff30b 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -691,7 +691,11 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_vacuum_count(C.oid) AS vacuum_count, pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count, pg_stat_get_analyze_count(C.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 2a7769b1fd..768e1b509e 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -299,6 +299,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, HeapTuple *rows; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; MemoryContext caller_context; Oid save_userid; int save_sec_context; @@ -344,8 +346,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +358,10 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -682,6 +685,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, in_outer_xact); } + elapsedtime = TimestampDifferenceMilliseconds(starttime, + GetCurrentTimestamp()); + /* * Now report ANALYZE to the cumulative stats system. For regular tables, * we do it only if not doing inherited stats. For partitioned tables, we @@ -693,9 +699,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), elapsedtime); else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) - pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL)); + pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), elapsedtime); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. @@ -732,8 +738,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* Log the action if appropriate */ if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 09247ba097..6a2033524a 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,20 +208,17 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples) + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); - TimestampTz ts; if (!pgstat_track_counts) return; - /* Store the data in the table's hash table entry. */ - ts = GetCurrentTimestamp(); - /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, tableoid, false); @@ -246,15 +243,20 @@ pgstat_report_vacuum(Oid tableoid, bool shared, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autovacuum_time = ts; + tabentry->last_autovacuum_time = endtime; tabentry->autovacuum_count++; } else { - tabentry->last_vacuum_time = ts; + tabentry->last_vacuum_time = endtime; tabentry->vacuum_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autovacuum_time += elapsedtime; + else + tabentry->total_vacuum_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* @@ -276,7 +278,7 @@ pgstat_report_vacuum(Oid tableoid, bool shared, void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter) + bool resetcounter, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; @@ -347,6 +349,11 @@ pgstat_report_analyze(Relation rel, tabentry->analyze_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autoanalyze_time += elapsedtime; + else + tabentry->total_analyze_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* see pgstat_report_vacuum() */ diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 5f8d20a406..e020fc4303 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -106,6 +106,34 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + float8 result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (float8) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_total_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_total_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_total_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_total_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index b37e8a6f88..4ca8430b67 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5540,6 +5540,22 @@ proname => 'pg_stat_get_autoanalyze_count', provolatile => 's', proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', prosrc => 'pg_stat_get_autoanalyze_count' }, +{ oid => '8406', descr => 'total vacuum time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_time' }, +{ oid => '8407', descr => 'total autovacuum time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_time' }, +{ oid => '8408', descr => 'total analyze time, in milliseconds', + proname => 'pg_stat_get_total_analyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_analyze_time' }, +{ oid => '8409', descr => 'total autoanalyze time, in milliseconds', + proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autoanalyze_time' }, { oid => '1936', descr => 'statistics: currently active backend IDs', proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't', provolatile => 's', proparallel => 'r', prorettype => 'int4', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 6475889c58..5ce2d5d718 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -502,6 +502,11 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -676,10 +681,11 @@ extern void pgstat_assoc_relation(Relation rel); extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples); + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, PgStat_Counter elapsedtime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 3014d047fe..33f631dafa 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) @@ -2188,7 +2192,11 @@ pg_stat_sys_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); pg_stat_user_functions| SELECT p.oid AS funcid, @@ -2236,7 +2244,11 @@ pg_stat_user_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); pg_stat_wal| SELECT wal_records, -- 2.40.1 ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-15 13:11 Bertrand Drouvot <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Bertrand Drouvot @ 2025-01-15 13:11 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: pgsql-hackers Hi, On Tue, Jan 14, 2025 at 05:01:52PM -0600, Sami Imseih wrote: > Please see the attached v3. Thanks! A few comments: === 1 + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>bigint</type> + </para> Those new fields should be documented as "double precision". === 2 +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + float8 result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (float8) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} I did propose "double" up-thread to be consistent with the code around. That would mean to also cast to "double". That's just for consistency purpose. What do you think? Appart from the above that LGTM. Regards, -- Bertrand Drouvot PostgreSQL Contributors Team RDS Open Source Databases Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-15 17:09 Sami Imseih <[email protected]> parent: Bertrand Drouvot <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-15 17:09 UTC (permalink / raw) To: Bertrand Drouvot <[email protected]>; +Cc: pgsql-hackers > Appart from the above that LGTM. thanks! I took care of your comments. I was not sure about the need to cast "double" but as you mention this is consistent with other parts of pgstatfuncs.c v4 attached. Regards, Sami Attachments: [application/octet-stream] v4-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch (16.2K, ../../CAA5RZ0s8=wd-X4GgMcFQO1WbwPtw4HjTtMcDahsnegZ8p6tYPQ@mail.gmail.com/2-v4-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch) download | inline diff: From 4575cb08c1144f4deb030d192ed3291b68e5d166 Mon Sep 17 00:00:00 2001 From: EC2 Default User <[email protected]> Date: Wed, 15 Jan 2025 15:55:20 +0000 Subject: [PATCH v4 1/1] Track per relation cumulative time spent in vacuum or analyze Added cumulative counter fields in pg_stat_all_tables for (auto)vacuum and (auto)analyze. This will allow a user to derive the average time spent for these operations with the help of the exiting (auto)vacuum_count and (auto)analyze_count fields. Author: Sami Imseih Reviewed-by: Bertrand Drouvot Discussion: https://www.postgresql.org/message-id/CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL%2BoUftuoz%2B%3DY1g%40mail.gmail.com --- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ src/backend/access/heap/vacuumlazy.c | 18 +++++++--- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 18 ++++++---- src/backend/utils/activity/pgstat_relation.c | 23 +++++++----- src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/test/regress/expected/rules.out | 18 ++++++++-- 9 files changed, 149 insertions(+), 26 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5888fae2b..2ff37a47a3 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4053,6 +4053,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in manual vacuum, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in vacuum by the autovacuum + daemon, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in manual analyze, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in analyze by the autovacuum + daemon, in milliseconds + </para></entry> + </row> </tbody> </tgroup> </table> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 09fab08b8e..432359e548 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -319,6 +319,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allvisible; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; WalUsage startwalusage = pgWalUsage; @@ -329,10 +331,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, verbose = (params->options & VACOPT_VERBOSE) != 0; instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)); + if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -340,6 +342,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } + starttime = GetCurrentTimestamp(); + pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -591,6 +595,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->NewRelfrozenXid, vacrel->NewRelminMxid, &frozenxid_updated, &minmulti_updated, false); + pgstat_progress_end_command(); + + endtime = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime); + /* * Report results to the cumulative stats system, too. * @@ -605,13 +614,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); - pgstat_progress_end_command(); + vacrel->missed_dead_tuples, + endtime, + elapsedtime); if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 64a873a16e..d4a531661c 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -691,7 +691,11 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_vacuum_count(C.oid) AS vacuum_count, pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count, pg_stat_get_analyze_count(C.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 2a7769b1fd..768e1b509e 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -299,6 +299,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, HeapTuple *rows; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; MemoryContext caller_context; Oid save_userid; int save_sec_context; @@ -344,8 +346,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +358,10 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -682,6 +685,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, in_outer_xact); } + elapsedtime = TimestampDifferenceMilliseconds(starttime, + GetCurrentTimestamp()); + /* * Now report ANALYZE to the cumulative stats system. For regular tables, * we do it only if not doing inherited stats. For partitioned tables, we @@ -693,9 +699,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), elapsedtime); else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) - pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL)); + pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), elapsedtime); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. @@ -732,8 +738,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* Log the action if appropriate */ if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 09247ba097..6a2033524a 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,20 +208,17 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples) + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); - TimestampTz ts; if (!pgstat_track_counts) return; - /* Store the data in the table's hash table entry. */ - ts = GetCurrentTimestamp(); - /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, tableoid, false); @@ -246,15 +243,20 @@ pgstat_report_vacuum(Oid tableoid, bool shared, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autovacuum_time = ts; + tabentry->last_autovacuum_time = endtime; tabentry->autovacuum_count++; } else { - tabentry->last_vacuum_time = ts; + tabentry->last_vacuum_time = endtime; tabentry->vacuum_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autovacuum_time += elapsedtime; + else + tabentry->total_vacuum_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* @@ -276,7 +278,7 @@ pgstat_report_vacuum(Oid tableoid, bool shared, void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter) + bool resetcounter, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; @@ -347,6 +349,11 @@ pgstat_report_analyze(Relation rel, tabentry->analyze_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autoanalyze_time += elapsedtime; + else + tabentry->total_analyze_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* see pgstat_report_vacuum() */ diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 0f5e0a9778..df2d6f93e5 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -106,6 +106,34 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + double result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (double) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_total_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_total_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_total_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_total_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index ba02ba53b2..f9b0405e46 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5540,6 +5540,22 @@ proname => 'pg_stat_get_autoanalyze_count', provolatile => 's', proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', prosrc => 'pg_stat_get_autoanalyze_count' }, +{ oid => '8406', descr => 'total vacuum time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_time' }, +{ oid => '8407', descr => 'total autovacuum time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_time' }, +{ oid => '8408', descr => 'total analyze time, in milliseconds', + proname => 'pg_stat_get_total_analyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_analyze_time' }, +{ oid => '8409', descr => 'total autoanalyze time, in milliseconds', + proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autoanalyze_time' }, { oid => '1936', descr => 'statistics: currently active backend IDs', proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't', provolatile => 's', proparallel => 'r', prorettype => 'int4', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 454a2cce0e..c3eb7197a7 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -461,6 +461,11 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -636,10 +641,11 @@ extern void pgstat_assoc_relation(Relation rel); extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples); + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, PgStat_Counter elapsedtime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 29580c9071..a50ab74f26 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) @@ -2190,7 +2194,11 @@ pg_stat_sys_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); pg_stat_user_functions| SELECT p.oid AS funcid, @@ -2238,7 +2246,11 @@ pg_stat_user_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); pg_stat_wal| SELECT wal_records, -- 2.40.1 ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-17 13:42 Bertrand Drouvot <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Bertrand Drouvot @ 2025-01-17 13:42 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: pgsql-hackers Hi, On Wed, Jan 15, 2025 at 11:09:00AM -0600, Sami Imseih wrote: > > Appart from the above that LGTM. > > thanks! I took care of your comments. Thanks! > I was not sure > about the need to cast "double" but as you mention this > is consistent with other parts of pgstatfuncs.c Yup. > v4 attached. One comment: + PG_RETURN_FLOAT8(result); \ The "\" indentation looks wrong for this line (was ok in v3). Regards, -- Bertrand Drouvot PostgreSQL Contributors Team RDS Open Source Databases Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-17 15:42 Sami Imseih <[email protected]> parent: Bertrand Drouvot <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-17 15:42 UTC (permalink / raw) To: Bertrand Drouvot <[email protected]>; +Cc: pgsql-hackers > One comment: > > + PG_RETURN_FLOAT8(result); \ > > The "\" indentation looks wrong for this line (was ok in v3). > > Regards, > Indeed. Corrected in v5 Thanks! Sami Attachments: [application/octet-stream] v5-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch (16.2K, ../../CAA5RZ0vKWKULGZ_V8DOOtFHXtsOLMVLCpkJ+guniB66T-o_eZA@mail.gmail.com/2-v5-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch) download | inline diff: From 05832b61936e60e591b53e796371417f06285a1d Mon Sep 17 00:00:00 2001 From: EC2 Default User <[email protected]> Date: Fri, 17 Jan 2025 15:23:01 +0000 Subject: [PATCH v5 1/1] Track per relation cumulative time spent in vacuum or analyze Added cumulative counter fields in pg_stat_all_tables for (auto)vacuum and (auto)analyze. This will allow a user to derive the average time spent for these operations with the help of the exiting (auto)vacuum_count and (auto)analyze_count fields. Author: Sami Imseih Reviewed-by: Bertrand Drouvot Discussion: https://www.postgresql.org/message-id/CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL%2BoUftuoz%2B%3DY1g%40mail.gmail.com --- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ src/backend/access/heap/vacuumlazy.c | 18 +++++++--- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 18 ++++++---- src/backend/utils/activity/pgstat_relation.c | 23 +++++++----- src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/test/regress/expected/rules.out | 18 ++++++++-- 9 files changed, 149 insertions(+), 26 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5888fae2b..2ff37a47a3 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4053,6 +4053,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in manual vacuum, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in vacuum by the autovacuum + daemon, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in manual analyze, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in analyze by the autovacuum + daemon, in milliseconds + </para></entry> + </row> </tbody> </tgroup> </table> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 5b0e790e12..3369542d6a 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -373,6 +373,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allvisible; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; WalUsage startwalusage = pgWalUsage; @@ -383,10 +385,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, verbose = (params->options & VACOPT_VERBOSE) != 0; instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)); + if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -394,6 +396,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } + starttime = GetCurrentTimestamp(); + pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -645,6 +649,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->NewRelfrozenXid, vacrel->NewRelminMxid, &frozenxid_updated, &minmulti_updated, false); + pgstat_progress_end_command(); + + endtime = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime); + /* * Report results to the cumulative stats system, too. * @@ -659,13 +668,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); - pgstat_progress_end_command(); + vacrel->missed_dead_tuples, + endtime, + elapsedtime); if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 46868bf7e8..cddc3ea9b5 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -696,7 +696,11 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_vacuum_count(C.oid) AS vacuum_count, pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count, pg_stat_get_analyze_count(C.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 2a7769b1fd..768e1b509e 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -299,6 +299,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, HeapTuple *rows; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; MemoryContext caller_context; Oid save_userid; int save_sec_context; @@ -344,8 +346,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +358,10 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -682,6 +685,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, in_outer_xact); } + elapsedtime = TimestampDifferenceMilliseconds(starttime, + GetCurrentTimestamp()); + /* * Now report ANALYZE to the cumulative stats system. For regular tables, * we do it only if not doing inherited stats. For partitioned tables, we @@ -693,9 +699,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), elapsedtime); else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) - pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL)); + pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), elapsedtime); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. @@ -732,8 +738,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* Log the action if appropriate */ if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 09247ba097..6a2033524a 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,20 +208,17 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples) + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); - TimestampTz ts; if (!pgstat_track_counts) return; - /* Store the data in the table's hash table entry. */ - ts = GetCurrentTimestamp(); - /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, tableoid, false); @@ -246,15 +243,20 @@ pgstat_report_vacuum(Oid tableoid, bool shared, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autovacuum_time = ts; + tabentry->last_autovacuum_time = endtime; tabentry->autovacuum_count++; } else { - tabentry->last_vacuum_time = ts; + tabentry->last_vacuum_time = endtime; tabentry->vacuum_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autovacuum_time += elapsedtime; + else + tabentry->total_vacuum_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* @@ -276,7 +278,7 @@ pgstat_report_vacuum(Oid tableoid, bool shared, void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter) + bool resetcounter, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; @@ -347,6 +349,11 @@ pgstat_report_analyze(Relation rel, tabentry->analyze_count++; } + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autoanalyze_time += elapsedtime; + else + tabentry->total_analyze_time += elapsedtime; + pgstat_unlock_entry(entry_ref); /* see pgstat_report_vacuum() */ diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 0f5e0a9778..e9096a8849 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -106,6 +106,34 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + double result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (double) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_total_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_total_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_total_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_total_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 18560755d2..03f90ef25d 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5540,6 +5540,22 @@ proname => 'pg_stat_get_autoanalyze_count', provolatile => 's', proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', prosrc => 'pg_stat_get_autoanalyze_count' }, +{ oid => '8406', descr => 'total vacuum time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_time' }, +{ oid => '8407', descr => 'total autovacuum time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_time' }, +{ oid => '8408', descr => 'total analyze time, in milliseconds', + proname => 'pg_stat_get_total_analyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_analyze_time' }, +{ oid => '8409', descr => 'total autoanalyze time, in milliseconds', + proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autoanalyze_time' }, { oid => '1936', descr => 'statistics: currently active backend IDs', proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't', provolatile => 's', proparallel => 'r', prorettype => 'int4', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 2d40fe3e70..1ab2b1578f 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -465,6 +465,11 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -640,10 +645,11 @@ extern void pgstat_assoc_relation(Relation rel); extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples); + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, PgStat_Counter elapsedtime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 856a8349c5..3361f6a69c 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) @@ -2190,7 +2194,11 @@ pg_stat_sys_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); pg_stat_user_functions| SELECT p.oid AS funcid, @@ -2238,7 +2246,11 @@ pg_stat_user_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); pg_stat_wal| SELECT wal_records, -- 2.40.1 ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-20 03:25 Michael Paquier <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Michael Paquier @ 2025-01-20 03:25 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers On Fri, Jan 17, 2025 at 09:42:13AM -0600, Sami Imseih wrote: > Indeed. Corrected in v5 I can get behind the idea of the patch. + PgStat_Counter total_vacuum_time; + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; These are time values in milliseconds. It would be good to document that as a comment with these fields, like PgStat_CheckpointerStats and others. Perhaps they should be grouped with their related counters within PgStat_StatTabEntry? Or not. The patch makes sense here in terms of passing down to pgstat_report_vacuum() the elapsed time and the end time to avoid an extra GetCurrentTimestamp() when calculating if the logging should happen. However in analyze.c.. +++ b/src/backend/commands/analyze.c [...] + TimestampTz endtime = 0; [...] - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, This is incorrect, endtime is never set. I would give priority to the symmetry of the code here, using for the analyze reporting the same arguments as the vacuum bits, so as we don't call GetCurrentTimestamp in the proposed changes for pgstat_report_analyze(). + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autovacuum_time += elapsedtime; + else + tabentry->total_vacuum_time += elapsedtime; [...] + if (AmAutoVacuumWorkerProcess()) + tabentry->total_autoanalyze_time += elapsedtime; + else + tabentry->total_analyze_time += elapsedtime; These could be grouped with their previous blocks. -- Michael Attachments: [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc) download ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-20 17:04 Sami Imseih <[email protected]> parent: Michael Paquier <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-20 17:04 UTC (permalink / raw) To: Michael Paquier <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers > I can get behind the idea of the patch. Thanks for the review! > + PgStat_Counter total_vacuum_time; > + PgStat_Counter total_autovacuum_time; > + PgStat_Counter total_analyze_time; > + PgStat_Counter total_autoanalyze_time; > } PgStat_StatTabEntry; > These are time values in milliseconds. It would be good to document > that as a comment with these fields, like PgStat_CheckpointerStats and > others. Perhaps they should be grouped with their related counters > within PgStat_StatTabEntry? Or not. done, including grouping all the vacuum counters together. > This is incorrect, endtime is never set. indeed. fixed. > I would give priority to the > symmetry of the code here, using for the analyze reporting the same > arguments as the vacuum bits, so as we don't call GetCurrentTimestamp > in the proposed changes for pgstat_report_analyze(). I agree. pgstat_report_analyze and pgstat_report_vacuum match will now take endtime and elapsedtime and we can remove the GetCurrentTimestamp inside pgstat_report_analyze. > + if (AmAutoVacuumWorkerProcess()) > + tabentry->total_autovacuum_time += elapsedtime; > + else > + tabentry->total_vacuum_time += elapsedtime; > [...] > + if (AmAutoVacuumWorkerProcess()) > + tabentry->total_autoanalyze_time += elapsedtime; > + else > + tabentry->total_analyze_time += elapsedtime; > Correct. fixed as well. See the attached v6. Thanks! Regards, Sami Attachments: [application/octet-stream] v6-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch (16.6K, ../../CAA5RZ0su2Unc+iJkhL6QEfsbjj6-WXjRWyf2E0b4BotUH=o4FA@mail.gmail.com/2-v6-0001-Track-per-relation-cumulative-time-spent-in-vacuu.patch) download | inline diff: From 92b5a28712cf4bd5ca6cb6bc34d56f78a37d5b4b Mon Sep 17 00:00:00 2001 From: EC2 Default User <[email protected]> Date: Mon, 20 Jan 2025 16:17:07 +0000 Subject: [PATCH v6 1/1] Track per relation cumulative time spent in vacuum or analyze Added cumulative counter fields in pg_stat_all_tables for (auto)vacuum and (auto)analyze. This will allow a user to derive the average time spent for these operations with the help of the exiting (auto)vacuum_count and (auto)analyze_count fields. Author: Sami Imseih Reviewed-by: Bertrand Drouvot, Michael Paquier Discussion: https://www.postgresql.org/message-id/CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL%2BoUftuoz%2B%3DY1g%40mail.gmail.com --- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ src/backend/access/heap/vacuumlazy.c | 18 +++++++--- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 18 ++++++---- src/backend/utils/activity/pgstat_relation.c | 22 ++++++------ src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/test/regress/expected/rules.out | 18 ++++++++-- 9 files changed, 146 insertions(+), 28 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5888fae2b..2ff37a47a3 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4053,6 +4053,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in manual vacuum, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in vacuum by the autovacuum + daemon, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in manual analyze, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has spent in analyze by the autovacuum + daemon, in milliseconds + </para></entry> + </row> </tbody> </tgroup> </table> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 5b0e790e12..3369542d6a 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -373,6 +373,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allvisible; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; PgStat_Counter startreadtime = 0, startwritetime = 0; WalUsage startwalusage = pgWalUsage; @@ -383,10 +385,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, verbose = (params->options & VACOPT_VERBOSE) != 0; instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)); + if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -394,6 +396,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } + starttime = GetCurrentTimestamp(); + pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -645,6 +649,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->NewRelfrozenXid, vacrel->NewRelminMxid, &frozenxid_updated, &minmulti_updated, false); + pgstat_progress_end_command(); + + endtime = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime); + /* * Report results to the cumulative stats system, too. * @@ -659,13 +668,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); - pgstat_progress_end_command(); + vacrel->missed_dead_tuples, + endtime, + elapsedtime); if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 46868bf7e8..cddc3ea9b5 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -696,7 +696,11 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_vacuum_count(C.oid) AS vacuum_count, pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count, pg_stat_get_analyze_count(C.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 2a7769b1fd..af3784d1f7 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -299,6 +299,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, HeapTuple *rows; PGRUsage ru0; TimestampTz starttime = 0; + TimestampTz endtime = 0; + PgStat_Counter elapsedtime = 0; MemoryContext caller_context; Oid save_userid; int save_sec_context; @@ -344,8 +346,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +358,10 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -682,6 +685,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, in_outer_xact); } + endtime = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, endtime); + /* * Now report ANALYZE to the cumulative stats system. For regular tables, * we do it only if not doing inherited stats. For partitioned tables, we @@ -693,9 +699,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), endtime, elapsedtime); else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) - pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL)); + pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), endtime, elapsedtime); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. @@ -732,8 +738,6 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* Log the action if appropriate */ if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); - if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 09247ba097..fab9a8d024 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,20 +208,17 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples) + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); - TimestampTz ts; if (!pgstat_track_counts) return; - /* Store the data in the table's hash table entry. */ - ts = GetCurrentTimestamp(); - /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, tableoid, false); @@ -246,13 +243,15 @@ pgstat_report_vacuum(Oid tableoid, bool shared, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autovacuum_time = ts; + tabentry->last_autovacuum_time = endtime; tabentry->autovacuum_count++; + tabentry->total_autovacuum_time += elapsedtime; } else { - tabentry->last_vacuum_time = ts; + tabentry->last_vacuum_time = endtime; tabentry->vacuum_count++; + tabentry->total_vacuum_time += elapsedtime; } pgstat_unlock_entry(entry_ref); @@ -276,7 +275,8 @@ pgstat_report_vacuum(Oid tableoid, bool shared, void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter) + bool resetcounter, TimestampTz endtime, + PgStat_Counter elapsedtime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; @@ -338,13 +338,15 @@ pgstat_report_analyze(Relation rel, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autoanalyze_time = GetCurrentTimestamp(); + tabentry->last_autoanalyze_time = endtime; tabentry->autoanalyze_count++; + tabentry->total_autoanalyze_time += elapsedtime; } else { - tabentry->last_analyze_time = GetCurrentTimestamp(); + tabentry->last_analyze_time = endtime; tabentry->analyze_count++; + tabentry->total_analyze_time += elapsedtime; } pgstat_unlock_entry(entry_ref); diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 0f5e0a9778..e9096a8849 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -106,6 +106,34 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + double result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (double) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_total_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_total_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_total_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_total_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 18560755d2..03f90ef25d 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5540,6 +5540,22 @@ proname => 'pg_stat_get_autoanalyze_count', provolatile => 's', proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', prosrc => 'pg_stat_get_autoanalyze_count' }, +{ oid => '8406', descr => 'total vacuum time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_time' }, +{ oid => '8407', descr => 'total autovacuum time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_time' }, +{ oid => '8408', descr => 'total analyze time, in milliseconds', + proname => 'pg_stat_get_total_analyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_analyze_time' }, +{ oid => '8409', descr => 'total autoanalyze time, in milliseconds', + proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autoanalyze_time' }, { oid => '1936', descr => 'statistics: currently active backend IDs', proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't', provolatile => 's', proparallel => 'r', prorettype => 'int4', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 2d40fe3e70..73378f65d2 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -465,6 +465,10 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + PgStat_Counter total_vacuum_time; /* times in milliseconds */ + PgStat_Counter total_autovacuum_time; /* times in milliseconds */ + PgStat_Counter total_analyze_time; /* times in milliseconds */ + PgStat_Counter total_autoanalyze_time; /* times in milliseconds */ } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -640,10 +644,12 @@ extern void pgstat_assoc_relation(Relation rel); extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples); + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz endtime, PgStat_Counter elapsedtime); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, TimestampTz endtime, + PgStat_Counter elapsedtime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 856a8349c5..3361f6a69c 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) @@ -2190,7 +2194,11 @@ pg_stat_sys_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); pg_stat_user_functions| SELECT p.oid AS funcid, @@ -2238,7 +2246,11 @@ pg_stat_user_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); pg_stat_wal| SELECT wal_records, -- 2.40.1 ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-24 07:32 Michael Paquier <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Michael Paquier @ 2025-01-24 07:32 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers On Mon, Jan 20, 2025 at 11:04:40AM -0600, Sami Imseih wrote: >> + PgStat_Counter total_vacuum_time; >> + PgStat_Counter total_autovacuum_time; >> + PgStat_Counter total_analyze_time; >> + PgStat_Counter total_autoanalyze_time; >> } PgStat_StatTabEntry; >> These are time values in milliseconds. It would be good to document >> that as a comment with these fields, like PgStat_CheckpointerStats and >> others. Perhaps they should be grouped with their related counters >> within PgStat_StatTabEntry? Or not. > > done, including grouping all the vacuum counters together. I was referring to the order of the fields in the structure itself, but that's no big deal one way or the other. > See the attached v6. + PgStat_Counter total_vacuum_time; /* times in milliseconds */ + PgStat_Counter total_autovacuum_time; /* times in milliseconds */ + PgStat_Counter total_analyze_time; /* times in milliseconds */ + PgStat_Counter total_autoanalyze_time; /* times in milliseconds */ This should be one comment for the whole block, or this should use the singular for each comment. instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0)); + if (instrument) Some noise. if (instrument) { - TimestampTz endtime = GetCurrentTimestamp(); On HEAD in the ANALYZE path, the endtime is calculated after index_vacuum_cleanup(). Your patch calculates it before index_vacuum_cleanup(), which would result in an incorrect calculation if the index cleanup takes a long time with less logs generated, no? Sorry for not noticing that earlier on the thread.. Perhaps it would be just better to pass the start time to pgstat_report_vacuum() and pgstat_report_analyze() then let their internals do the elapsed time calculations. Consistency of the arguments for both functions is something worth having, IMO, even if it means a bit more GetCurrentTimestamp() in this case. -- Michael Attachments: [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc) download ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-24 20:19 Sami Imseih <[email protected]> parent: Michael Paquier <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-24 20:19 UTC (permalink / raw) To: Michael Paquier <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers > I was referring to the order of the fields in the structure itself, > but that's no big deal one way or the other. I understand your point now. I will group them with the related counters in the next rev and will use > This should be one comment for the whole block, or this should use the > singular for each comment. I will use a singular "/* time in milliseconds */" comment for each new field. This existing write_time field is plural, but I will leave that one alone for now. PgStat_Counter write_time; /* times in milliseconds */ > On HEAD in the ANALYZE path, the endtime is calculated after > index_vacuum_cleanup(). Your patch calculates it before > index_vacuum_cleanup(), which would result in an incorrect calculation > if the index cleanup takes a long time with less logs generated, no? > Sorry for not noticing that earlier on the thread.. Perhaps it would > be just better to pass the start time to pgstat_report_vacuum() and > pgstat_report_analyze() then let their internals do the elapsed time > calculations. Consistency of the arguments for both functions is > something worth having, IMO, even if it means a bit more > GetCurrentTimestamp() in this case. So currently, the report of the last_(autoanalyze|analyze)_time is set before the index_vacuum_cleanup, but for logging purposes the elapsed time is calculated afterwards. Most users will not notice this, but I think that is wrong as well. I think we should calculate endtime and elapsedtime and call pgstat_report_analyze after the index_vacuum_cleanup; and before vac_close_indexes. This is more accurate and will avoid incurring the extra GetCurrentTimestamp() call. What do you think? Regards, Sami ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-27 00:30 Michael Paquier <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Michael Paquier @ 2025-01-27 00:30 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers On Fri, Jan 24, 2025 at 02:19:59PM -0600, Sami Imseih wrote: > So currently, the report of the last_(autoanalyze|analyze)_time > is set before the index_vacuum_cleanup, but for logging purposes > the elapsed time is calculated afterwards. Most users will not notice > this, but I think that is wrong as well. > > I think we should calculate endtime and elapsedtime and call > pgstat_report_analyze after the index_vacuum_cleanup; and > before vac_close_indexes. This is more accurate and will > avoid incurring the extra GetCurrentTimestamp() call. > > What do you think? I think that this is hiding a behavior change while adding new counters, and both changes are independent. Another thing that is slightly incorrect to do if we take the argument of only adding the counters is moving around the call of pgstat_progress_end_command(), because it's not really wrong as-is, either. I'd suggest to make all that a separate discussion. The addition of the extra GetCurrentTimestamp() in the report path does not stress me much, FWIW, and keeping the tracking of the end time within the report routines for [auto]analyze and [auto]vacuum has the merit that the caller does not need to worry about more TimestampDifferenceMilliseconds() calculations. I have put my hands on this patch, and at the end I think that we should just do the attached, which is simpler and addresses your use-case. Note also that the end time is acquired while the entries are not locked in the report routines, and some tweaks in the docs and comments. -- Michael Attachments: [text/x-diff] v7-0001-Track-per-relation-cumulative-time-spent-in-auto-.patch (15.2K, ../../[email protected]/2-v7-0001-Track-per-relation-cumulative-time-spent-in-auto-.patch) download | inline diff: From 456325d581a1a28b49e82de48172b19fca8b204a Mon Sep 17 00:00:00 2001 From: Michael Paquier <[email protected]> Date: Mon, 27 Jan 2025 09:23:55 +0900 Subject: [PATCH v7] Track per relation cumulative time spent in [auto]vacuum and [auto]analyze This commit adds four fields to the statistics of relations, aggregating the amount of time spent for each operation on a relation: - total_vacuum_time, for manual vacuum. - total_autovacuum_time, for autovacuum. - total_analyze_time, for manual analyze. - total_autoanalyze_time, for autoanalyze. This gives users the option to derive the average time spent for these operations with the help of the related "count" fields. XXX: catversion bump XXX: stats version bump Author: Sami Imseih Reviewed-by: Bertrand Drouvot, Michael Paquier Discussion: https://www.postgresql.org/message-id/CAA5RZ0uVOGBYmPEeGF2d1B_67tgNjKx_bKDuL%2BoUftuoz%2B%3DY1g%40mail.gmail.com --- src/include/catalog/pg_proc.dat | 16 +++++++++ src/include/pgstat.h | 10 ++++-- src/backend/access/heap/vacuumlazy.c | 7 ++-- src/backend/catalog/system_views.sql | 6 +++- src/backend/commands/analyze.c | 12 ++++--- src/backend/utils/activity/pgstat_relation.c | 21 ++++++++--- src/backend/utils/adt/pgstatfuncs.c | 28 +++++++++++++++ src/test/regress/expected/rules.out | 18 ++++++++-- doc/src/sgml/monitoring.sgml | 38 ++++++++++++++++++++ 9 files changed, 139 insertions(+), 17 deletions(-) diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 2aafdbc3e93..5b8c2ad2a54 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5543,6 +5543,22 @@ proname => 'pg_stat_get_autoanalyze_count', provolatile => 's', proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', prosrc => 'pg_stat_get_autoanalyze_count' }, +{ oid => '8406', descr => 'total vacuum time, in milliseconds', + proname => 'pg_stat_get_total_vacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_vacuum_time' }, +{ oid => '8407', descr => 'total autovacuum time, in milliseconds', + proname => 'pg_stat_get_total_autovacuum_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autovacuum_time' }, +{ oid => '8408', descr => 'total analyze time, in milliseconds', + proname => 'pg_stat_get_total_analyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_analyze_time' }, +{ oid => '8409', descr => 'total autoanalyze time, in milliseconds', + proname => 'pg_stat_get_total_autoanalyze_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_total_autoanalyze_time' }, { oid => '1936', descr => 'statistics: currently active backend IDs', proname => 'pg_stat_get_backend_idset', prorows => '100', proretset => 't', provolatile => 's', proparallel => 'r', prorettype => 'int4', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index d0d45150977..ea6889d7090 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -465,6 +465,11 @@ typedef struct PgStat_StatTabEntry PgStat_Counter analyze_count; TimestampTz last_autoanalyze_time; /* autovacuum initiated */ PgStat_Counter autoanalyze_count; + + PgStat_Counter total_vacuum_time; /* times in milliseconds */ + PgStat_Counter total_autovacuum_time; + PgStat_Counter total_analyze_time; + PgStat_Counter total_autoanalyze_time; } PgStat_StatTabEntry; typedef struct PgStat_WalStats @@ -649,10 +654,11 @@ extern void pgstat_assoc_relation(Relation rel); extern void pgstat_unlink_relation(Relation rel); extern void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples); + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz starttime); extern void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter); + bool resetcounter, TimestampTz starttime); /* * If stats are enabled, but pending data hasn't been prepared yet, call diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 5b0e790e121..5ed43e43914 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -386,7 +386,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, if (instrument) { pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); if (track_io_timing) { startreadtime = pgStatBlockReadTime; @@ -394,6 +393,9 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } + /* Used for instrumentation and stats report */ + starttime = GetCurrentTimestamp(); + pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -659,7 +661,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, rel->rd_rel->relisshared, Max(vacrel->new_live_tuples, 0), vacrel->recently_dead_tuples + - vacrel->missed_dead_tuples); + vacrel->missed_dead_tuples, + starttime); pgstat_progress_end_command(); if (instrument) diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 46868bf7e89..cddc3ea9b53 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -696,7 +696,11 @@ CREATE VIEW pg_stat_all_tables AS pg_stat_get_vacuum_count(C.oid) AS vacuum_count, pg_stat_get_autovacuum_count(C.oid) AS autovacuum_count, pg_stat_get_analyze_count(C.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(C.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(C.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(C.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(C.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(C.oid) AS total_autoanalyze_time FROM pg_class C LEFT JOIN pg_index I ON C.oid = I.indrelid LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 2a7769b1fd1..f8da32e9aef 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -344,8 +344,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* - * measure elapsed time if called with verbose or if autovacuum logging - * requires it + * When verbose or autovacuum logging is used, initialize a resource usage + * snapshot and optionally track I/O timing. */ if (instrument) { @@ -356,9 +356,11 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } pg_rusage_init(&ru0); - starttime = GetCurrentTimestamp(); } + /* Used for instrumentation and stats report */ + starttime = GetCurrentTimestamp(); + /* * Determine which columns to analyze * @@ -693,9 +695,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ if (!inh) pgstat_report_analyze(onerel, totalrows, totaldeadrows, - (va_cols == NIL)); + (va_cols == NIL), starttime); else if (onerel->rd_rel->relkind == RELKIND_PARTITIONED_TABLE) - pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL)); + pgstat_report_analyze(onerel, 0, 0, (va_cols == NIL), starttime); /* * If this isn't part of VACUUM ANALYZE, let index AMs do cleanup. diff --git a/src/backend/utils/activity/pgstat_relation.c b/src/backend/utils/activity/pgstat_relation.c index 965a7fe2c64..d64595a165c 100644 --- a/src/backend/utils/activity/pgstat_relation.c +++ b/src/backend/utils/activity/pgstat_relation.c @@ -208,19 +208,22 @@ pgstat_drop_relation(Relation rel) */ void pgstat_report_vacuum(Oid tableoid, bool shared, - PgStat_Counter livetuples, PgStat_Counter deadtuples) + PgStat_Counter livetuples, PgStat_Counter deadtuples, + TimestampTz starttime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (shared ? InvalidOid : MyDatabaseId); TimestampTz ts; + PgStat_Counter elapsedtime; if (!pgstat_track_counts) return; /* Store the data in the table's hash table entry. */ ts = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, ts); /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, @@ -248,11 +251,13 @@ pgstat_report_vacuum(Oid tableoid, bool shared, { tabentry->last_autovacuum_time = ts; tabentry->autovacuum_count++; + tabentry->total_autovacuum_time += elapsedtime; } else { tabentry->last_vacuum_time = ts; tabentry->vacuum_count++; + tabentry->total_vacuum_time += elapsedtime; } pgstat_unlock_entry(entry_ref); @@ -276,12 +281,14 @@ pgstat_report_vacuum(Oid tableoid, bool shared, void pgstat_report_analyze(Relation rel, PgStat_Counter livetuples, PgStat_Counter deadtuples, - bool resetcounter) + bool resetcounter, TimestampTz starttime) { PgStat_EntryRef *entry_ref; PgStatShared_Relation *shtabentry; PgStat_StatTabEntry *tabentry; Oid dboid = (rel->rd_rel->relisshared ? InvalidOid : MyDatabaseId); + TimestampTz ts; + PgStat_Counter elapsedtime; if (!pgstat_track_counts) return; @@ -315,6 +322,10 @@ pgstat_report_analyze(Relation rel, deadtuples = Max(deadtuples, 0); } + /* Store the data in the table's hash table entry. */ + ts = GetCurrentTimestamp(); + elapsedtime = TimestampDifferenceMilliseconds(starttime, ts); + /* block acquiring lock for the same reason as pgstat_report_autovac() */ entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_RELATION, dboid, RelationGetRelid(rel), @@ -338,13 +349,15 @@ pgstat_report_analyze(Relation rel, if (AmAutoVacuumWorkerProcess()) { - tabentry->last_autoanalyze_time = GetCurrentTimestamp(); + tabentry->last_autoanalyze_time = ts; tabentry->autoanalyze_count++; + tabentry->total_autoanalyze_time += elapsedtime; } else { - tabentry->last_analyze_time = GetCurrentTimestamp(); + tabentry->last_analyze_time = ts; tabentry->analyze_count++; + tabentry->total_analyze_time += elapsedtime; } pgstat_unlock_entry(entry_ref); diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 0f5e0a9778d..e9096a88492 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -106,6 +106,34 @@ PG_STAT_GET_RELENTRY_INT64(tuples_updated) /* pg_stat_get_vacuum_count */ PG_STAT_GET_RELENTRY_INT64(vacuum_count) +#define PG_STAT_GET_RELENTRY_FLOAT8(stat) \ +Datum \ +CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ +{ \ + Oid relid = PG_GETARG_OID(0); \ + double result; \ + PgStat_StatTabEntry *tabentry; \ + \ + if ((tabentry = pgstat_fetch_stat_tabentry(relid)) == NULL) \ + result = 0; \ + else \ + result = (double) (tabentry->stat); \ + \ + PG_RETURN_FLOAT8(result); \ +} + +/* pg_stat_get_total_vacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_vacuum_time) + +/* pg_stat_get_total_autovacuum_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autovacuum_time) + +/* pg_stat_get_total_analyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_analyze_time) + +/* pg_stat_get_total_autoanalyze_time */ +PG_STAT_GET_RELENTRY_FLOAT8(total_autoanalyze_time) + #define PG_STAT_GET_RELENTRY_TIMESTAMPTZ(stat) \ Datum \ CppConcat(pg_stat_get_,stat)(PG_FUNCTION_ARGS) \ diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 856a8349c50..3361f6a69c9 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1804,7 +1804,11 @@ pg_stat_all_tables| SELECT c.oid AS relid, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, - pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count + pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count, + pg_stat_get_total_vacuum_time(c.oid) AS total_vacuum_time, + pg_stat_get_total_autovacuum_time(c.oid) AS total_autovacuum_time, + pg_stat_get_total_analyze_time(c.oid) AS total_analyze_time, + pg_stat_get_total_autoanalyze_time(c.oid) AS total_autoanalyze_time FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) @@ -2190,7 +2194,11 @@ pg_stat_sys_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (schemaname ~ '^pg_toast'::text)); pg_stat_user_functions| SELECT p.oid AS funcid, @@ -2238,7 +2246,11 @@ pg_stat_user_tables| SELECT relid, vacuum_count, autovacuum_count, analyze_count, - autoanalyze_count + autoanalyze_count, + total_vacuum_time, + total_autovacuum_time, + total_analyze_time, + total_autoanalyze_time FROM pg_stat_all_tables WHERE ((schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (schemaname !~ '^pg_toast'::text)); pg_stat_wal| SELECT wal_records, diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5888fae2b5..0bdb51eedb9 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -4053,6 +4053,44 @@ description | Waiting for a newly initialized WAL file to reach durable storage daemon </para></entry> </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_vacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been vacuumed, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autovacuum_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been vacuumed by the autovacuum daemon, + in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_analyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been analyzed, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>total_autoanalyze_time</structfield> <type>double precision</type> + </para> + <para> + Total time this table has been analyzed by the autovacuum daemon, + in milliseconds + </para></entry> + </row> </tbody> </tgroup> </table> -- 2.47.2 [application/pgp-signature] signature.asc (833B, ../../[email protected]/3-signature.asc) download ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-27 13:31 Bertrand Drouvot <[email protected]> parent: Michael Paquier <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Bertrand Drouvot @ 2025-01-27 13:31 UTC (permalink / raw) To: Michael Paquier <[email protected]>; +Cc: Sami Imseih <[email protected]>; pgsql-hackers Hi, On Mon, Jan 27, 2025 at 09:30:16AM +0900, Michael Paquier wrote: > The addition of the extra GetCurrentTimestamp() in the report path > does not stress me much, Reading at the previous messages I see how you reached this state. I also think that makes sense and that's not an issue as we are not in a hot path here. > should just do the attached, which is simpler and addresses your > use-case. Note also that the end time is acquired while the entries > are not locked in the report routines, and some tweaks in the docs and > comments. LGTM. Regards, -- Bertrand Drouvot PostgreSQL Contributors Team RDS Open Source Databases Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-27 17:22 Sami Imseih <[email protected]> parent: Bertrand Drouvot <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Sami Imseih @ 2025-01-27 17:22 UTC (permalink / raw) To: Bertrand Drouvot <[email protected]>; +Cc: Michael Paquier <[email protected]>; pgsql-hackers > I think that this is hiding a behavior change while adding new > counters, and both changes are independent. That's a fair point. > Another thing that is > slightly incorrect to do if we take the argument of only adding the > counters is moving around the call of pgstat_progress_end_command(), > because it's not really wrong as-is, either. I'd suggest to make all > that a separate discussion. Yeah, we have inconsistency between when vacuum and analyze command ends as well as inconsistency between the time reported to pg_stats vs the logs. I will start a follow-up thread for this. > I have put my hands on this patch, and at the end I think that we > should just do the attached, which is simpler and addresses your > use-case. Note also that the end time is acquired while the entries > are not locked in the report routines, and some tweaks in the docs and > comments. Thanks for the update. This LGTM. Regards, Sami ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-01-28 00:59 Michael Paquier <[email protected]> parent: Sami Imseih <[email protected]> 0 siblings, 1 reply; 19+ messages in thread From: Michael Paquier @ 2025-01-28 00:59 UTC (permalink / raw) To: Sami Imseih <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers On Mon, Jan 27, 2025 at 11:22:16AM -0600, Sami Imseih wrote: >> I have put my hands on this patch, and at the end I think that we >> should just do the attached, which is simpler and addresses your >> use-case. Note also that the end time is acquired while the entries >> are not locked in the report routines, and some tweaks in the docs and >> comments. > > Thanks for the update. This LGTM. Okidoki. Done, then, with bumps for the catalog version and the stats file version. -- Michael Attachments: [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc) download ^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: POC: track vacuum/analyze cumulative time per relation @ 2025-02-04 13:06 Alena Rybakina <[email protected]> parent: Michael Paquier <[email protected]> 0 siblings, 0 replies; 19+ messages in thread From: Alena Rybakina @ 2025-02-04 13:06 UTC (permalink / raw) To: Michael Paquier <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers; Sami Imseih <[email protected]> Hi! On 28.01.2025 03:59, Michael Paquier wrote: > On Mon, Jan 27, 2025 at 11:22:16AM -0600, Sami Imseih wrote: >>> I have put my hands on this patch, and at the end I think that we >>> should just do the attached, which is simpler and addresses your >>> use-case. Note also that the end time is acquired while the entries >>> are not locked in the report routines, and some tweaks in the docs and >>> comments. >> Thanks for the update. This LGTM. > Okidoki. Done, then, with bumps for the catalog version and the stats > file version. You might be interested in looking at my patch for collecting vacuum statistics? Same issue, but it collects more information about the vacuum procedure for relations and databases. I mentioned it here [0] in the current thread. [0] https://www.postgresql.org/message-id/Z4U3hkWuEgByhGgJ%40ip-10-97-1-34.eu-west-3.compute.internal -- Regards, Alena Rybakina Postgres Professional ^ permalink raw reply [nested|flat] 19+ messages in thread
end of thread, other threads:[~2025-02-04 13:06 UTC | newest] Thread overview: 19+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2019-02-21 00:04 [PATCH 2/5] Optimize jsonb operator #>> using extracted JsonbValueAsText() Nikita Glukhov <[email protected]> 2023-07-26 10:49 [PATCH v3 4/7] Row pattern recognition patch (executor). Tatsuo Ishii <[email protected]> 2025-01-10 15:09 Re: POC: track vacuum/analyze cumulative time per relation Bertrand Drouvot <[email protected]> 2025-01-10 22:26 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-13 15:55 ` Re: POC: track vacuum/analyze cumulative time per relation Bertrand Drouvot <[email protected]> 2025-01-14 23:01 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-15 13:11 ` Re: POC: track vacuum/analyze cumulative time per relation Bertrand Drouvot <[email protected]> 2025-01-15 17:09 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-17 13:42 ` Re: POC: track vacuum/analyze cumulative time per relation Bertrand Drouvot <[email protected]> 2025-01-17 15:42 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-20 03:25 ` Re: POC: track vacuum/analyze cumulative time per relation Michael Paquier <[email protected]> 2025-01-20 17:04 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-24 07:32 ` Re: POC: track vacuum/analyze cumulative time per relation Michael Paquier <[email protected]> 2025-01-24 20:19 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-27 00:30 ` Re: POC: track vacuum/analyze cumulative time per relation Michael Paquier <[email protected]> 2025-01-27 13:31 ` Re: POC: track vacuum/analyze cumulative time per relation Bertrand Drouvot <[email protected]> 2025-01-27 17:22 ` Re: POC: track vacuum/analyze cumulative time per relation Sami Imseih <[email protected]> 2025-01-28 00:59 ` Re: POC: track vacuum/analyze cumulative time per relation Michael Paquier <[email protected]> 2025-02-04 13:06 ` Re: POC: track vacuum/analyze cumulative time per relation Alena Rybakina <[email protected]>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox