On Fri, Feb 25, 2022 at 5:43 PM Julien Rouhaud <rjuju...@gmail.com> wrote:
>
> On Fri, Feb 25, 2022 at 05:38:45PM +0100, Magnus Hagander wrote:
> >
> > Per some off-list discussion with Julien, we have clearly been talking
> > in slightly different terms. So let's summarize the options into what
> > theÿ́d actually be:
> >
> > Option 0: what is int he patch now
> >
> > Option 1:
> > jit_count - number of executions using jit
> > total_jit_time - for sum of functions+inlining+optimization+emission time
> > min_jit_time - for sum of functions+inlining+optimization+emission time
> > max_jit_time - for sum of functions+inlining+optimization+emission time
> > mean_jit_time - for sum of functions+inlining+optimization+emission time
> > stddev_jit_time - for sum of functions+inlining+optimization+emission time
> > jit_functions - number of functions
> > jit_inlining_count - number of executions where inlining happened
> > jit_optimization_count - number of executions where optimization happened
> > jit_emission_count - number of executions where emission happened
> >
> > Option 2:
> > jit_count
> > jit_functions
> > jit_generation_time
> > jit_inlining_count
> > jit_inlining_time
> > jit_optimization_count
> > jit_optimization_time
> > jit_emission_count
> > jit_emission_time
>
> I'm for option 2, I think it's important to have the timing details for
> inlining and optimization and be able to compute correct stats.
I wonder if there might be an interesting middle ground, or if that is
making it too much. That is, we could have an
Option 3:
jit_count
total_jit_time - for sum of functions+inlining+optimization+emission time
min_jit_time - for sum of functions+inlining+optimization+emission time
max_jit_time - for sum of functions+inlining+optimization+emission time
mean_jit_time - for sum of functions+inlining+optimization+emission time
stddev_jit_time - for sum of functions+inlining+optimization+emission time
jit_functions
jit_generation_time
jit_inlining_count
jit_inlining_time
jit_optimization_count
jit_optimization_time
jit_emission_count
jit_emission_time
That is, we'd get the more detailed timings across the total time, but
not on the details. But that might be overkill.
But -- here's an updated patched based on Option 2.
--
Magnus Hagander
Me: https://www.hagander.net/
Work: https://www.redpill-linpro.com/
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 7fabd96f38..d9eacfb364 100644
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -6,7 +6,7 @@ OBJS = \
pg_stat_statements.o
EXTENSION = pg_stat_statements
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.8--1.9.sql \
+DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.9--1.10.sql pg_stat_statements--1.8--1.9.sql \
pg_stat_statements--1.7--1.8.sql pg_stat_statements--1.6--1.7.sql \
pg_stat_statements--1.5--1.6.sql pg_stat_statements--1.4--1.5.sql \
pg_stat_statements--1.3--1.4.sql pg_stat_statements--1.2--1.3.sql \
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
new file mode 100644
index 0000000000..8924df2715
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
@@ -0,0 +1,65 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.10'" to load this file. \quit
+
+/* First we have to remove them from the extension */
+ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements;
+ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean);
+
+/* Then we can drop them */
+DROP VIEW pg_stat_statements;
+DROP FUNCTION pg_stat_statements(boolean);
+
+/* Now redefine */
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+ OUT userid oid,
+ OUT dbid oid,
+ OUT toplevel bool,
+ OUT queryid bigint,
+ OUT query text,
+ OUT plans int8,
+ OUT total_plan_time float8,
+ OUT min_plan_time float8,
+ OUT max_plan_time float8,
+ OUT mean_plan_time float8,
+ OUT stddev_plan_time float8,
+ OUT calls int8,
+ OUT total_exec_time float8,
+ OUT min_exec_time float8,
+ OUT max_exec_time float8,
+ OUT mean_exec_time float8,
+ OUT stddev_exec_time float8,
+ OUT rows int8,
+ OUT shared_blks_hit int8,
+ OUT shared_blks_read int8,
+ OUT shared_blks_dirtied int8,
+ OUT shared_blks_written int8,
+ OUT local_blks_hit int8,
+ OUT local_blks_read int8,
+ OUT local_blks_dirtied int8,
+ OUT local_blks_written int8,
+ OUT temp_blks_read int8,
+ OUT temp_blks_written int8,
+ OUT blk_read_time float8,
+ OUT blk_write_time float8,
+ OUT wal_records int8,
+ OUT wal_fpi int8,
+ OUT wal_bytes numeric,
+ OUT jit_functions int8,
+ OUT jit_generation_time float8,
+ OUT jit_inlining_count int8,
+ OUT jit_inlining_time float8,
+ OUT jit_optimization_count int8,
+ OUT jit_optimization_time float8,
+ OUT jit_emission_count int8,
+ OUT jit_emission_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_10'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+ SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index d803253cea..99b9db37b1 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -52,6 +52,7 @@
#include "common/hashfn.h"
#include "executor/instrument.h"
#include "funcapi.h"
+#include "jit/jit.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
#include "optimizer/planner.h"
@@ -121,7 +122,8 @@ typedef enum pgssVersion
PGSS_V1_2,
PGSS_V1_3,
PGSS_V1_8,
- PGSS_V1_9
+ PGSS_V1_9,
+ PGSS_V1_10
} pgssVersion;
typedef enum pgssStoreKind
@@ -189,6 +191,17 @@ typedef struct Counters
int64 wal_records; /* # of WAL records generated */
int64 wal_fpi; /* # of WAL full page images generated */
uint64 wal_bytes; /* total amount of WAL generated in bytes */
+ int64 jit_functions; /* total number of JIT functions emitted */
+ double jit_generation_time; /* total time to generate jit code */
+ int64 jit_inlining_count; /* number of times inlining time has been
+ * > 0 */
+ double jit_inlining_time; /* total time to inline jit code */
+ int64 jit_optimization_count; /* number of times optimization time
+ * has been > 0 */
+ double jit_optimization_time; /* total time to optimize jit code */
+ int64 jit_emission_count; /* number of times emission time has been
+ * > 0 */
+ double jit_emission_time; /* total time to emit jit code */
} Counters;
/*
@@ -302,6 +315,7 @@ PG_FUNCTION_INFO_V1(pg_stat_statements_1_2);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_3);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_8);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_9);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_10);
PG_FUNCTION_INFO_V1(pg_stat_statements);
PG_FUNCTION_INFO_V1(pg_stat_statements_info);
@@ -330,6 +344,7 @@ static void pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
pgssVersion api_version,
@@ -854,6 +869,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jstate)
0,
NULL,
NULL,
+ NULL,
jstate);
}
@@ -938,6 +954,7 @@ pgss_planner(Query *parse,
0,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1056,6 +1073,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
&queryDesc->totaltime->walusage,
+ queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL,
NULL);
}
@@ -1173,6 +1191,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
rows,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1206,6 +1225,7 @@ pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate)
{
pgssHashKey key;
@@ -1373,6 +1393,23 @@ pgss_store(const char *query, uint64 queryId,
e->counters.wal_records += walusage->wal_records;
e->counters.wal_fpi += walusage->wal_fpi;
e->counters.wal_bytes += walusage->wal_bytes;
+ if (jitusage)
+ {
+ e->counters.jit_functions += jitusage->created_functions;
+ e->counters.jit_generation_time += INSTR_TIME_GET_MILLISEC(jitusage->generation_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter))
+ e->counters.jit_inlining_count++;
+ e->counters.jit_inlining_time += INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter))
+ e->counters.jit_optimization_count++;
+ e->counters.jit_optimization_time += INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->emission_counter))
+ e->counters.jit_emission_count++;
+ e->counters.jit_emission_time += INSTR_TIME_GET_MILLISEC(jitusage->emission_counter);
+ }
SpinLockRelease(&e->mutex);
}
@@ -1422,7 +1459,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_3 23
#define PG_STAT_STATEMENTS_COLS_V1_8 32
#define PG_STAT_STATEMENTS_COLS_V1_9 33
-#define PG_STAT_STATEMENTS_COLS 33 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_10 41
+#define PG_STAT_STATEMENTS_COLS 41 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1434,6 +1472,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
* expected API version is identified by embedding it in the C name of the
* function. Unfortunately we weren't bright enough to do that for 1.1.
*/
+Datum
+pg_stat_statements_1_10(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_10, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_9(PG_FUNCTION_ARGS)
{
@@ -1567,6 +1615,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (api_version != PGSS_V1_9)
elog(ERROR, "incorrect number of output arguments");
break;
+ case PG_STAT_STATEMENTS_COLS_V1_10:
+ if (api_version != PGSS_V1_10)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1791,6 +1843,17 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
Int32GetDatum(-1));
values[i++] = wal_bytes;
}
+ if (api_version >= PGSS_V1_10)
+ {
+ values[i++] = Int64GetDatumFast(tmp.jit_functions);
+ values[i++] = Float8GetDatumFast(tmp.jit_generation_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_inlining_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_inlining_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_optimization_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_optimization_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_emission_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_emission_time);
+ }
Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 :
api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
@@ -1798,6 +1861,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
api_version == PGSS_V1_3 ? PG_STAT_STATEMENTS_COLS_V1_3 :
api_version == PGSS_V1_8 ? PG_STAT_STATEMENTS_COLS_V1_8 :
api_version == PGSS_V1_9 ? PG_STAT_STATEMENTS_COLS_V1_9 :
+ api_version == PGSS_V1_10 ? PG_STAT_STATEMENTS_COLS_V1_10 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 2f1ce6ed50..0747e48138 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.control
+++ b/contrib/pg_stat_statements/pg_stat_statements.control
@@ -1,5 +1,5 @@
# pg_stat_statements extension
comment = 'track planning and execution statistics of all SQL statements executed'
-default_version = '1.9'
+default_version = '1.10'
module_pathname = '$libdir/pg_stat_statements'
relocatable = true
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index bc9d5bdbe3..f3d65cfe2a 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -379,6 +379,78 @@
Total amount of WAL generated by the statement in bytes
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_functions</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total number of functions JIT-compiled by the statement
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_generation_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on generating JIT code, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times functions have been inlined
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on inlining functions, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times the statement has been inlined
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_optimization_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on optimizing, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times code has been emitted
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_emission_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on emitting code, in milliseconds
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
