On Tue, Mar 22, 2022 at 12:50 AM Andres Freund <and...@anarazel.de> wrote:
> Hi,
>
> On 2022-03-07 13:10:32 +0100, Magnus Hagander wrote:
> > Meanwhile here is an updated based on your other comments above, as
> > well as those from Julien.
>
> This fails on cfbot, due to compiler warnings:
> https://cirrus-ci.com/task/5127667648299008?logs=mingw_cross_warning#L390
Huh. That's annoying. I forgot int64 is %d on linux and %lld on Windows :/
PFA a fix for that.
--
Magnus Hagander
Me: https://www.hagander.net/ <http://www.hagander.net/>
Work: https://www.redpill-linpro.com/ <http://www.redpill-linpro.com/>
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 05df48131d..4831fc362c 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6618,6 +6618,21 @@ local0.* /var/log/postgresql
</listitem>
</varlistentry>
+ <varlistentry id="guc-jit-warn-above-fraction" xreflabel="jit_warn_above_fraction">
+ <term><varname>jit_warn_above_fraction</varname> (<type>floating point</type>)
+ <indexterm>
+ <primary><varname>jit_warn_above_fraction</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Causes a warning to be written to the log if the time spent on JIT (see <xref linkend="jit"/>)
+ goes above this fraction of the total query runtime.
+ A value of 0 (the default) disables the warning.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-startup-progress-interval" xreflabel="log_startup_progress_interval">
<term><varname>log_startup_progress_interval</varname> (<type>integer</type>)
<indexterm>
diff --git a/src/backend/tcop/fastpath.c b/src/backend/tcop/fastpath.c
index d429aa4663..a1bff893a3 100644
--- a/src/backend/tcop/fastpath.c
+++ b/src/backend/tcop/fastpath.c
@@ -196,6 +196,7 @@ HandleFunctionRequest(StringInfo msgBuf)
struct fp_info *fip;
bool callit;
bool was_logged = false;
+ int msecs;
char msec_str[32];
/*
@@ -305,7 +306,7 @@ HandleFunctionRequest(StringInfo msgBuf)
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, was_logged))
+ switch (check_log_duration(&msecs, msec_str, was_logged))
{
case 1:
ereport(LOG,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index ba2fcfeb4a..cd7c076b7c 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -998,7 +998,9 @@ exec_simple_query(const char *query_string)
bool save_log_statement_stats = log_statement_stats;
bool was_logged = false;
bool use_implicit_block;
+ int msecs;
char msec_str[32];
+ int64 jit_time = 0;
/*
* Report query to various monitoring facilities.
@@ -1257,6 +1259,16 @@ exec_simple_query(const char *query_string)
receiver->rDestroy(receiver);
+ /* Collect JIT timings in case it's active */
+ if (jit_enabled && jit_warn_above_fraction > 0 && portal->queryDesc && portal->queryDesc->estate->es_jit)
+ {
+ jit_time +=
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.generation_counter) +
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.inlining_counter) +
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.optimization_counter) +
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.emission_counter);
+ }
+
PortalDrop(portal, false);
if (lnext(parsetree_list, parsetree_item) == NULL)
@@ -1327,7 +1339,7 @@ exec_simple_query(const char *query_string)
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, was_logged))
+ switch (check_log_duration(&msecs, msec_str, was_logged))
{
case 1:
ereport(LOG,
@@ -1343,6 +1355,16 @@ exec_simple_query(const char *query_string)
break;
}
+ if (jit_enabled && jit_warn_above_fraction > 0)
+ {
+ if (jit_time > msecs * jit_warn_above_fraction)
+ {
+ ereport(WARNING,
+ (errmsg("JIT total processing time was %lld ms of %d ms",
+ (long long) jit_time, msecs)));
+ }
+ }
+
if (save_log_statement_stats)
ShowUsage("QUERY STATISTICS");
@@ -1370,6 +1392,7 @@ exec_parse_message(const char *query_string, /* string to execute */
CachedPlanSource *psrc;
bool is_named;
bool save_log_statement_stats = log_statement_stats;
+ int msecs;
char msec_str[32];
/*
@@ -1563,7 +1586,7 @@ exec_parse_message(const char *query_string, /* string to execute */
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, false))
+ switch (check_log_duration(&msecs, msec_str, false))
{
case 1:
ereport(LOG,
@@ -1610,6 +1633,7 @@ exec_bind_message(StringInfo input_message)
MemoryContext oldContext;
bool save_log_statement_stats = log_statement_stats;
bool snapshot_set = false;
+ int msecs;
char msec_str[32];
ParamsErrorCbData params_data;
ErrorContextCallback params_errcxt;
@@ -2022,7 +2046,7 @@ exec_bind_message(StringInfo input_message)
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, false))
+ switch (check_log_duration(&msecs, msec_str, false))
{
case 1:
ereport(LOG,
@@ -2068,6 +2092,7 @@ exec_execute_message(const char *portal_name, long max_rows)
bool is_xact_command;
bool execute_is_fetch;
bool was_logged = false;
+ int msecs;
char msec_str[32];
ParamsErrorCbData params_data;
ErrorContextCallback params_errcxt;
@@ -2259,7 +2284,7 @@ exec_execute_message(const char *portal_name, long max_rows)
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, was_logged))
+ switch (check_log_duration(&msecs, msec_str, was_logged))
{
case 1:
ereport(LOG,
@@ -2282,6 +2307,22 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
}
+ if (jit_enabled && jit_warn_above_fraction > 0)
+ {
+ int64 jit_time =
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.generation_counter) +
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.inlining_counter) +
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.optimization_counter) +
+ INSTR_TIME_GET_MILLISEC(portal->queryDesc->estate->es_jit->instr.emission_counter);
+
+ if (jit_time > msecs * jit_warn_above_fraction)
+ {
+ ereport(WARNING,
+ (errmsg("JIT total processing time was %lld ms of %d ms",
+ (long long) jit_time, msecs)));
+ }
+ }
+
if (save_log_statement_stats)
ShowUsage("EXECUTE MESSAGE STATISTICS");
@@ -2328,6 +2369,10 @@ check_log_statement(List *stmt_list)
* 1 if just the duration should be logged
* 2 if duration and query details should be logged
*
+ * The millisecond runtime of the query is stored in msecs if any logging parameter
+ * that requires the calculation of time is enabled, even if the result is not that
+ * the entry should be logged. In other cases, it is set to -1.
+ *
* If logging is needed, the duration in msec is formatted into msec_str[],
* which must be a 32-byte buffer.
*
@@ -2335,14 +2380,13 @@ check_log_statement(List *stmt_list)
* essentially prevents 2 from being returned).
*/
int
-check_log_duration(char *msec_str, bool was_logged)
+check_log_duration(int *msecs, char *msec_str, bool was_logged)
{
if (log_duration || log_min_duration_sample >= 0 ||
- log_min_duration_statement >= 0 || xact_is_sampled)
+ log_min_duration_statement >= 0 || xact_is_sampled || jit_warn_above_fraction > 0)
{
long secs;
int usecs;
- int msecs;
bool exceeded_duration;
bool exceeded_sample_duration;
bool in_sample = false;
@@ -2350,7 +2394,7 @@ check_log_duration(char *msec_str, bool was_logged)
TimestampDifference(GetCurrentStatementStartTimestamp(),
GetCurrentTimestamp(),
&secs, &usecs);
- msecs = usecs / 1000;
+ *msecs = usecs / 1000;
/*
* This odd-looking test for log_min_duration_* being exceeded is
@@ -2360,12 +2404,12 @@ check_log_duration(char *msec_str, bool was_logged)
exceeded_duration = (log_min_duration_statement == 0 ||
(log_min_duration_statement > 0 &&
(secs > log_min_duration_statement / 1000 ||
- secs * 1000 + msecs >= log_min_duration_statement)));
+ secs * 1000 + *msecs >= log_min_duration_statement)));
exceeded_sample_duration = (log_min_duration_sample == 0 ||
(log_min_duration_sample > 0 &&
(secs > log_min_duration_sample / 1000 ||
- secs * 1000 + msecs >= log_min_duration_sample)));
+ secs * 1000 + *msecs >= log_min_duration_sample)));
/*
* Do not log if log_statement_sample_rate = 0. Log a sample if
@@ -2380,13 +2424,17 @@ check_log_duration(char *msec_str, bool was_logged)
if (exceeded_duration || in_sample || log_duration || xact_is_sampled)
{
snprintf(msec_str, 32, "%ld.%03d",
- secs * 1000 + msecs, usecs % 1000);
+ secs * 1000 + *msecs, usecs % 1000);
if ((exceeded_duration || in_sample || xact_is_sampled) && !was_logged)
return 2;
else
return 1;
}
}
+ else
+ {
+ *msecs = -1;
+ }
return 0;
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index b86137dc38..5cabc292ee 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -612,6 +612,7 @@ int log_parameter_max_length_on_error = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
+double jit_warn_above_fraction = 0;
int trace_recovery_messages = LOG;
char *backtrace_functions;
char *backtrace_symbol_list;
@@ -3889,6 +3890,19 @@ static struct config_real ConfigureNamesReal[] =
NULL, NULL, NULL
},
+ {
+ {"jit_warn_above_fraction", PGC_USERSET, LOGGING_WHEN,
+ gettext_noop("Sets the fraction of query time spent on JIT before writing "
+ "a warning to the log."),
+ gettext_noop("Write a message to the server log if more than this "
+ "fraction of the query runtime is spent on JIT. "
+ "Zero turns off the warning.")
+ },
+ &jit_warn_above_fraction,
+ 0.0, 0.0, 1.0,
+ NULL, NULL, NULL
+ },
+
/* End-of-list marker */
{
{NULL, 0, 0, NULL, NULL}, NULL, 0.0, 0.0, 0.0, NULL, NULL, NULL
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index b933fade8c..d04ace34c0 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -404,6 +404,8 @@
#jit_optimize_above_cost = 500000 # use expensive JIT optimizations if
# query is more expensive than this;
# -1 disables
+#jit_warn_above_fraction = 0 # warn if JIT is more than this fraction of
+ # query runtime. 0 disables.
# - Genetic Query Optimizer -
diff --git a/src/include/jit/jit.h b/src/include/jit/jit.h
index 707176d9ed..59b37d6dc0 100644
--- a/src/include/jit/jit.h
+++ b/src/include/jit/jit.h
@@ -89,6 +89,7 @@ extern bool jit_tuple_deforming;
extern double jit_above_cost;
extern double jit_inline_above_cost;
extern double jit_optimize_above_cost;
+extern double jit_warn_above_fraction;
extern void jit_reset_after_error(void);
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index 92291a750d..3f12f7fe25 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -87,7 +87,7 @@ extern void PostgresMain(const char *dbname,
extern long get_stack_depth_rlimit(void);
extern void ResetUsage(void);
extern void ShowUsage(const char *title);
-extern int check_log_duration(char *msec_str, bool was_logged);
+extern int check_log_duration(int *msec, char *msec_str, bool was_logged);
extern void set_debug_options(int debug_flag,
GucContext context, GucSource source);
extern bool set_plan_disabling_options(const char *arg,
