ne 18. 4. 2021 v 16:09 odesÃlatel Pavel Stehule <pavel.steh...@gmail.com>
napsal:
>
>
> ne 18. 4. 2021 v 14:28 odesÃlatel Julien Rouhaud <rjuju...@gmail.com>
> napsal:
>
>> On Sun, Apr 18, 2021 at 06:21:56AM +0200, Pavel Stehule wrote:
>> >
>> > The extension like pg_qualstat is good, but it does different work.
>>
>> Yes definitely. It was just an idea if you needed something right now
>> that
>> could more or less do what you needed, not saying that we shouldn't
>> improve the
>> core :)
>>
>> > In
>> > complex applications I need to detect buggy (forgotten) queries - last
>> week
>> > I found two queries over bigger tables without predicates. So the
>> qualstat
>> > doesn't help me.
>>
>> Also not totally helpful but powa was created to detect problematic
>> queries in
>> such cases. It wouldn't say if it's because of a seq scan or not (so yes
>> again
>> we need to improve that), but it would give you the slowest (or top
>> consumer
>> for any resource) for a given time interval.
>>
>> > This is an application for a government with few (but for
>> > government typical) specific: 1) the life cycle is short (one month), 2)
>> > there is not slow start - from first moment the application will be
>> used by
>> > more hundred thousands people, 3) the application is very public - so
>> any
>> > issues are very interesting for press and very unpleasant for politics,
>> and
>> > in next step for all suppliers (there are high penalty for failures),
>> and
>> > an admins are not happy from external extensions, 4) the budget is not
>> too
>> > big - there is not any performance testing environment
>> >
>> > First stages are covered well today. We can log and process very slow
>> > queries, and fix it immediately - with CREATE INDEX CONCURRENTLY I can
>> do
>> > it well on production servers too without high risk.
>> >
>> > But the detection of some bad not too slow queries is hard. And as an
>> > external consultant I am not able to install any external extensions to
>> the
>> > production environment for fixing some hot issues, The risk is not
>> > acceptable for project managers and I understand. So I have to use only
>> > tools available in Postgres.
>>
>> Yes I agree that having additional and more specialized tool in core
>> postgres
>> would definitely help in similar scenario.
>>
>> I think that having some kind of threshold for seq scan (like the
>> mentioned
>> auto_explain.log_seqscan = XXX) in auto_explain would be the best
>> approach, as
>> you really need the plan to know why a seq scan was chosen and if it was a
>> reasonable choice or not.
>>
>
> I would like to write this for core and for auto_explain too. I was in a
> situation when I hadnot used auto_explain too. Although this extension is
> widely used and then the risk is low.
>
> When I detect the query, then I can run the explanation manually. But sure
> I think so it can work well inside auto_explain
>
I tried to write the patch. It is harder work for core, than I expected,
because there is not any good information if the query is top or not, so it
is not easy to decide if we should log info or not.
On second hand, the modification of auto_explain is easy.
I am sending the patch
Regards
Pavel
> Regards
>
> Pavel
>
>
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 445bb37191..5754e25594 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -17,8 +17,11 @@
#include "access/parallel.h"
#include "commands/explain.h"
#include "executor/instrument.h"
+#include "nodes/nodeFuncs.h"
+#include "parser/parsetree.h"
#include "jit/jit.h"
#include "utils/guc.h"
+#include "utils/lsyscache.h"
PG_MODULE_MAGIC;
@@ -35,6 +38,7 @@ static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static int auto_explain_log_level = LOG;
static bool auto_explain_log_nested_statements = false;
static double auto_explain_sample_rate = 1;
+static int auto_explain_log_seqscan = -1; /* tuples */
static const struct config_enum_entry format_options[] = {
{"text", EXPLAIN_FORMAT_TEXT, false},
@@ -65,7 +69,7 @@ static int nesting_level = 0;
static bool current_query_sampled = false;
#define auto_explain_enabled() \
- (auto_explain_log_min_duration >= 0 && \
+ ((auto_explain_log_min_duration >= 0 || auto_explain_log_seqscan != -1) && \
(nesting_level == 0 || auto_explain_log_nested_statements) && \
current_query_sampled)
@@ -105,6 +109,18 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomIntVariable("auto_explain.log_seqscan",
+ "Sets the minimum tuples produced by sequantial scans which plans will be logged",
+ "Zero prints all plans that contains seqscan node. -1 turns this feature off.",
+ &auto_explain_log_seqscan,
+ -1,
+ -1, INT_MAX,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
DefineCustomBoolVariable("auto_explain.log_analyze",
"Use EXPLAIN ANALYZE for plan logging.",
NULL,
@@ -274,7 +290,9 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
*/
if (nesting_level == 0)
{
- if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
+ if ((auto_explain_log_min_duration >= 0 ||
+ auto_explain_log_seqscan != -1) &&
+ !IsParallelWorker())
current_query_sampled = (random() < auto_explain_sample_rate *
((double) MAX_RANDOM_VALUE + 1));
else
@@ -295,6 +313,10 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
if (auto_explain_log_wal)
queryDesc->instrument_options |= INSTRUMENT_WAL;
}
+
+ /* We need to know number of processed rows per node */
+ if (auto_explain_log_seqscan != -1 && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
+ queryDesc->instrument_options |= INSTRUMENT_ROWS;
}
if (prev_ExecutorStart)
@@ -363,16 +385,44 @@ explain_ExecutorFinish(QueryDesc *queryDesc)
PG_END_TRY();
}
+/*
+ * Colllect relations where log_seqscan limit was exceeded
+ */
+static bool
+DetectSeqScanOverLimit(PlanState *planstate, Bitmapset **rels)
+{
+ Plan *plan = planstate->plan;
+
+ if (planstate->instrument)
+ InstrEndLoop(planstate->instrument);
+
+ if (IsA(plan, SeqScan))
+ {
+ if (planstate->instrument &&
+ planstate->instrument->ntuples >= auto_explain_log_seqscan)
+ {
+ *rels = bms_add_member(*rels, ((Scan *) plan)->scanrelid);
+ }
+ }
+
+ return planstate_tree_walker(planstate, DetectSeqScanOverLimit, rels);
+}
+
/*
* ExecutorEnd hook: log results if needed
*/
static void
explain_ExecutorEnd(QueryDesc *queryDesc)
{
- if (queryDesc->totaltime && auto_explain_enabled())
+ if (auto_explain_enabled() &&
+ (queryDesc->totaltime || auto_explain_log_seqscan != -1))
{
MemoryContext oldcxt;
double msec;
+ Bitmapset *rels = NULL;
+ StringInfoData relnames;
+
+ relnames.data = NULL;
/*
* Make sure we operate in the per-query context, so any cruft will be
@@ -386,13 +436,37 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
*/
InstrEndLoop(queryDesc->totaltime);
+ if (auto_explain_log_seqscan != -1)
+ {
+ DetectSeqScanOverLimit(queryDesc->planstate, &rels);
+
+ if (rels)
+ {
+ int relid = -1;
+
+ initStringInfo(&relnames);
+
+ while ((relid = bms_next_member(rels, relid)) >= 0)
+ {
+ RangeTblEntry *rte;
+
+ if (*relnames.data != '\0')
+ appendStringInfoString(&relnames, ",");
+
+ rte = rt_fetch(relid, queryDesc->plannedstmt->rtable);
+ appendStringInfoString(&relnames, get_rel_name(rte->relid));
+ }
+ }
+ }
+
/* Log plan if duration is exceeded. */
msec = queryDesc->totaltime->total * 1000.0;
- if (msec >= auto_explain_log_min_duration)
+ if ((auto_explain_log_min_duration != -1 &&
+ msec >= auto_explain_log_min_duration) || rels)
{
ExplainState *es = NewExplainState();
- es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
+ es->analyze = (queryDesc->instrument_options && (auto_explain_log_analyze || auto_explain_log_seqscan != -1));
es->verbose = auto_explain_log_verbose;
es->buffers = (es->analyze && auto_explain_log_buffers);
es->wal = (es->analyze && auto_explain_log_wal);
@@ -427,10 +501,18 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
- ereport(auto_explain_log_level,
- (errmsg("duration: %.3f ms plan:\n%s",
- msec, es->str->data),
- errhidestmt(true)));
+ if (!relnames.data)
+ ereport(auto_explain_log_level,
+ (errmsg("duration: %.3f ms plan:\n%s",
+ msec, es->str->data),
+ errhidestmt(true)));
+ else
+ {
+ ereport(auto_explain_log_level,
+ (errmsg("duration: %.3f ms, over limit seqscans: %s, plan:\n%s",
+ msec, relnames.data, es->str->data),
+ errhidestmt(true)));
+ }
}
MemoryContextSwitchTo(oldcxt);
