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,