Add local blocks timing statistics columns local_blk_{write|read}_time

pull/463/head
Artem Gavrilov 2024-05-24 20:55:13 +02:00
parent cd6d836feb
commit 60a03d1c94
5 changed files with 69 additions and 47 deletions

View File

@ -65,11 +65,12 @@ CREATE FUNCTION pg_stat_monitor_internal(
OUT temp_blks_written int8, OUT temp_blks_written int8,
OUT shared_blk_read_time float8, OUT shared_blk_read_time float8,
OUT shared_blk_write_time float8, OUT shared_blk_write_time float8,
OUT local_blk_read_time float8,
OUT temp_blk_read_time float8, -- 45 OUT local_blk_write_time float8,
OUT temp_blk_read_time float8,
OUT temp_blk_write_time float8, OUT temp_blk_write_time float8,
OUT resp_calls text, -- 47 OUT resp_calls text, -- 49
OUT cpu_user_time float8, OUT cpu_user_time float8,
OUT cpu_sys_time float8, OUT cpu_sys_time float8,
OUT wal_records int8, OUT wal_records int8,
@ -77,7 +78,7 @@ CREATE FUNCTION pg_stat_monitor_internal(
OUT wal_bytes numeric, OUT wal_bytes numeric,
OUT comments TEXT, OUT comments TEXT,
OUT jit_functions int8, -- 54 OUT jit_functions int8, -- 56
OUT jit_generation_time float8, OUT jit_generation_time float8,
OUT jit_inlining_count int8, OUT jit_inlining_count int8,
OUT jit_inlining_time float8, OUT jit_inlining_time float8,
@ -86,7 +87,7 @@ CREATE FUNCTION pg_stat_monitor_internal(
OUT jit_emission_count int8, OUT jit_emission_count int8,
OUT jit_emission_time float8, OUT jit_emission_time float8,
OUT toplevel BOOLEAN, --62 OUT toplevel BOOLEAN, --64
OUT bucket_done BOOLEAN OUT bucket_done BOOLEAN
) )
RETURNS SETOF record RETURNS SETOF record
@ -407,6 +408,8 @@ CREATE VIEW pg_stat_monitor AS SELECT
temp_blks_written, temp_blks_written,
shared_blk_read_time, shared_blk_read_time,
shared_blk_write_time, shared_blk_write_time,
local_blk_read_time,
local_blk_write_time,
temp_blk_read_time, temp_blk_read_time,
temp_blk_write_time, temp_blk_write_time,

View File

@ -42,7 +42,7 @@ PG_MODULE_MAGIC;
/* Number of output arguments (columns) for various API versions */ /* Number of output arguments (columns) for various API versions */
#define PG_STAT_MONITOR_COLS_V1_0 52 #define PG_STAT_MONITOR_COLS_V1_0 52
#define PG_STAT_MONITOR_COLS_V2_0 64 #define PG_STAT_MONITOR_COLS_V2_0 64
#define PG_STAT_MONITOR_COLS_V2_1 64 //TODO !!!!!!! #define PG_STAT_MONITOR_COLS_V2_1 66 //TODO !!!!!!!
#define PG_STAT_MONITOR_COLS PG_STAT_MONITOR_COLS_V2_0 /* maximum of above */ #define PG_STAT_MONITOR_COLS PG_STAT_MONITOR_COLS_V2_0 /* maximum of above */
#define PGSM_TEXT_FILE PGSTAT_STAT_PERMANENT_DIRECTORY "pg_stat_monitor_query" #define PGSM_TEXT_FILE PGSTAT_STAT_PERMANENT_DIRECTORY "pg_stat_monitor_query"
@ -1528,6 +1528,8 @@ pgsm_update_entry(pgsmEntry * entry,
#else #else
e->counters.blocks.shared_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->shared_blk_read_time); e->counters.blocks.shared_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->shared_blk_read_time);
e->counters.blocks.shared_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->shared_blk_write_time); e->counters.blocks.shared_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->shared_blk_write_time);
e->counters.blocks.local_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->local_blk_read_time);
e->counters.blocks.local_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->local_blk_write_time);
#endif #endif
#if PG_VERSION_NUM >= 150000 #if PG_VERSION_NUM >= 150000
@ -1536,11 +1538,13 @@ pgsm_update_entry(pgsmEntry * entry,
#endif #endif
#if PG_VERSION_NUM < 170000 #if PG_VERSION_NUM < 170000
memcpy((void *) &e->counters.blocks.instr_blk_read_time, &bufusage->blk_read_time, sizeof(instr_time)); memcpy((void *) &e->counters.blocks.instr_shared_blk_read_time, &bufusage->blk_read_time, sizeof(instr_time));
memcpy((void *) &e->counters.blocks.instr_blk_write_time, &bufusage->blk_write_time, sizeof(instr_time)); memcpy((void *) &e->counters.blocks.instr_shared_blk_write_time, &bufusage->blk_write_time, sizeof(instr_time));
#else #else
memcpy((void *) &e->counters.blocks.instr_blk_read_time, &bufusage->shared_blk_read_time, sizeof(instr_time)); memcpy((void *) &e->counters.blocks.instr_shared_blk_read_time, &bufusage->shared_blk_read_time, sizeof(instr_time));
memcpy((void *) &e->counters.blocks.instr_blk_write_time, &bufusage->shared_blk_write_time, sizeof(instr_time)); memcpy((void *) &e->counters.blocks.instr_shared_blk_write_time, &bufusage->shared_blk_write_time, sizeof(instr_time));
memcpy((void *) &e->counters.blocks.instr_local_blk_write_time, &bufusage->local_blk_write_time, sizeof(instr_time));
memcpy((void *) &e->counters.blocks.instr_local_blk_write_time, &bufusage->local_blk_write_time, sizeof(instr_time));
#endif #endif
@ -1819,11 +1823,13 @@ pgsm_store(pgsmEntry * entry)
bufusage.temp_blks_written = entry->counters.blocks.temp_blks_written; bufusage.temp_blks_written = entry->counters.blocks.temp_blks_written;
#if PG_VERSION_NUM < 170000 #if PG_VERSION_NUM < 170000
memcpy(&bufusage.blk_read_time, &entry->counters.blocks.instr_blk_read_time, sizeof(instr_time)); memcpy(&bufusage.blk_read_time, &entry->counters.blocks.instr_shared_blk_read_time, sizeof(instr_time));
memcpy(&bufusage.blk_write_time, &entry->counters.blocks.instr_blk_write_time, sizeof(instr_time)); memcpy(&bufusage.blk_write_time, &entry->counters.blocks.instr_shared_blk_write_time, sizeof(instr_time));
#else #else
memcpy(&bufusage.shared_blk_read_time, &entry->counters.blocks.instr_blk_read_time, sizeof(instr_time)); memcpy(&bufusage.shared_blk_read_time, &entry->counters.blocks.instr_shared_blk_read_time, sizeof(instr_time));
memcpy(&bufusage.shared_blk_write_time, &entry->counters.blocks.instr_blk_write_time, sizeof(instr_time)); memcpy(&bufusage.shared_blk_write_time, &entry->counters.blocks.instr_shared_blk_write_time, sizeof(instr_time));
memcpy(&bufusage.local_blk_read_time, &entry->counters.blocks.instr_local_blk_read_time, sizeof(instr_time));
memcpy(&bufusage.local_blk_write_time, &entry->counters.blocks.instr_local_blk_write_time, sizeof(instr_time));
#endif #endif
#if PG_VERSION_NUM >= 150000 #if PG_VERSION_NUM >= 150000
@ -2391,7 +2397,7 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo,
/* stddev_plan_time at column number 32 */ /* stddev_plan_time at column number 32 */
values[i++] = Float8GetDatumFast(stddev); values[i++] = Float8GetDatumFast(stddev);
/* blocks are from column number 33 - 46 */ /* blocks are from column number 33 - 48 */
values[i++] = Int64GetDatumFast(tmp.blocks.shared_blks_hit); values[i++] = Int64GetDatumFast(tmp.blocks.shared_blks_hit);
values[i++] = Int64GetDatumFast(tmp.blocks.shared_blks_read); values[i++] = Int64GetDatumFast(tmp.blocks.shared_blks_read);
values[i++] = Int64GetDatumFast(tmp.blocks.shared_blks_dirtied); values[i++] = Int64GetDatumFast(tmp.blocks.shared_blks_dirtied);
@ -2404,25 +2410,27 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo,
values[i++] = Int64GetDatumFast(tmp.blocks.temp_blks_written); values[i++] = Int64GetDatumFast(tmp.blocks.temp_blks_written);
values[i++] = Float8GetDatumFast(tmp.blocks.shared_blk_read_time); values[i++] = Float8GetDatumFast(tmp.blocks.shared_blk_read_time);
values[i++] = Float8GetDatumFast(tmp.blocks.shared_blk_write_time); values[i++] = Float8GetDatumFast(tmp.blocks.shared_blk_write_time);
values[i++] = Float8GetDatumFast(tmp.blocks.local_blk_read_time);
values[i++] = Float8GetDatumFast(tmp.blocks.local_blk_write_time);
values[i++] = Float8GetDatumFast(tmp.blocks.temp_blk_read_time); values[i++] = Float8GetDatumFast(tmp.blocks.temp_blk_read_time);
values[i++] = Float8GetDatumFast(tmp.blocks.temp_blk_write_time); values[i++] = Float8GetDatumFast(tmp.blocks.temp_blk_write_time);
/* resp_calls at column number 47 */ /* resp_calls at column number 49 */
values[i++] = IntArrayGetTextDatum(tmp.resp_calls, hist_bucket_count_total); values[i++] = IntArrayGetTextDatum(tmp.resp_calls, hist_bucket_count_total);
/* cpu_user_time at column number 48 */ /* cpu_user_time at column number 50 */
values[i++] = Float8GetDatumFast(tmp.sysinfo.utime); values[i++] = Float8GetDatumFast(tmp.sysinfo.utime);
/* cpu_sys_time at column number 49 */ /* cpu_sys_time at column number 51 */
values[i++] = Float8GetDatumFast(tmp.sysinfo.stime); values[i++] = Float8GetDatumFast(tmp.sysinfo.stime);
{ {
char buf[256]; char buf[256];
Datum wal_bytes; Datum wal_bytes;
/* wal_records at column number 50 */ /* wal_records at column number 52 */
values[i++] = Int64GetDatumFast(tmp.walusage.wal_records); values[i++] = Int64GetDatumFast(tmp.walusage.wal_records);
/* wal_fpi at column number 51 */ /* wal_fpi at column number 53 */
values[i++] = Int64GetDatumFast(tmp.walusage.wal_fpi); values[i++] = Int64GetDatumFast(tmp.walusage.wal_fpi);
snprintf(buf, sizeof buf, UINT64_FORMAT, tmp.walusage.wal_bytes); snprintf(buf, sizeof buf, UINT64_FORMAT, tmp.walusage.wal_bytes);
@ -2432,16 +2440,16 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo,
CStringGetDatum(buf), CStringGetDatum(buf),
ObjectIdGetDatum(0), ObjectIdGetDatum(0),
Int32GetDatum(-1)); Int32GetDatum(-1));
/* wal_bytes at column number 52 */ /* wal_bytes at column number 54 */
values[i++] = wal_bytes; values[i++] = wal_bytes;
/* application_name at column number 53 */ /* application_name at column number 55 */
if (strlen(tmp.info.comments) > 0) if (strlen(tmp.info.comments) > 0)
values[i++] = CStringGetTextDatum(tmp.info.comments); values[i++] = CStringGetTextDatum(tmp.info.comments);
else else
nulls[i++] = true; nulls[i++] = true;
/* blocks are from column number 54 - 61 */ /* blocks are from column number 56 - 63 */
values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_functions); values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_functions);
values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_generation_time); values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_generation_time);
values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_inlining_count); values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_inlining_count);
@ -2451,10 +2459,10 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo,
values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_emission_count); values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_emission_count);
values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_emission_time); values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_emission_time);
} }
/* toplevel at column number 62 */ /* toplevel at column number 64 */
values[i++] = BoolGetDatum(toplevel); values[i++] = BoolGetDatum(toplevel);
/* bucket_done at column number 63 */ /* bucket_done at column number 65 */
values[i++] = BoolGetDatum(pg_atomic_read_u64(&pgsm->current_wbucket) != bucketid); values[i++] = BoolGetDatum(pg_atomic_read_u64(&pgsm->current_wbucket) != bucketid);
/* clean up and return the tuplestore */ /* clean up and return the tuplestore */

View File

@ -286,17 +286,19 @@ typedef struct Blocks
int64 temp_blks_written; /* # of temp blocks written */ int64 temp_blks_written; /* # of temp blocks written */
double shared_blk_read_time; /* time spent reading shared blocks, in msec */ double shared_blk_read_time; /* time spent reading shared blocks, in msec */
double shared_blk_write_time; /* time spent writing shared blocks, in msec */ double shared_blk_write_time; /* time spent writing shared blocks, in msec */
double local_blk_read_time; /* time spent reading local blocks, in msec */
double local_blk_write_time; /* time spent writing local blocks, in msec */
double temp_blk_read_time; /* time spent reading temp blocks, in msec */ double temp_blk_read_time; /* time spent reading temp blocks, in msec */
double temp_blk_write_time; /* time spent writing temp blocks, in double temp_blk_write_time; /* time spent writing temp blocks, in msec */
* msec */
/* /*
* Variables for local entry. The values to be passed to pgsm_update_entry * Variables for local entry. The values to be passed to pgsm_update_entry
* from pgsm_store. * from pgsm_store.
*/ */
instr_time instr_blk_read_time; /* time spent reading blocks */ instr_time instr_shared_blk_read_time; /* time spent reading shared blocks */
instr_time instr_blk_write_time; /* time spent writing blocks */ instr_time instr_shared_blk_write_time; /* time spent writing shared blocks */
instr_time instr_local_blk_read_time; /* time spent reading local blocks */
instr_time instr_local_blk_write_time; /* time spent writing local blocks */
instr_time instr_temp_blk_read_time; /* time spent reading temp blocks */ instr_time instr_temp_blk_read_time; /* time spent reading temp blocks */
instr_time instr_temp_blk_write_time; /* time spent writing temp blocks */ instr_time instr_temp_blk_write_time; /* time spent writing temp blocks */
} Blocks; } Blocks;

View File

@ -28,8 +28,8 @@ my %pg_versions_pgsm_columns = ( 17 => "application_name,".
"datname,dbid,elevel,jit_emission_count,jit_emission_time,jit_functions," . "datname,dbid,elevel,jit_emission_count,jit_emission_time,jit_functions," .
"jit_generation_time,jit_inlining_count,jit_inlining_time," . "jit_generation_time,jit_inlining_count,jit_inlining_time," .
"jit_optimization_count,jit_optimization_time," . "jit_optimization_count,jit_optimization_time," .
"local_blks_dirtied,local_blks_hit,local_blks_read," . "local_blk_read_time,local_blk_write_time,local_blks_dirtied,local_blks_hit,".
"local_blks_written,max_exec_time,max_plan_time,mean_exec_time," . "local_blks_read,local_blks_written,max_exec_time,max_plan_time,mean_exec_time," .
"mean_plan_time,message,min_exec_time,min_plan_time,pgsm_query_id,planid," . "mean_plan_time,message,min_exec_time,min_plan_time,pgsm_query_id,planid," .
"plans,query,query_plan,queryid,relations,resp_calls,rows," . "plans,query,query_plan,queryid,relations,resp_calls,rows," .
"shared_blk_read_time,shared_blk_write_time,shared_blks_dirtied," . "shared_blk_read_time,shared_blk_write_time,shared_blks_dirtied," .

View File

@ -70,10 +70,19 @@ is($stdout,'t',"Check: local_blks_hit should not be 0.");
trim($stdout); trim($stdout);
is($stdout,'t',"Check: local_blks_dirtied should not be 0."); is($stdout,'t',"Check: local_blks_dirtied should not be 0.");
($cmdret, $stdout, $stderr) = $node->psql('postgres', 'SELECT SUM(PGSM.local_blk_write_time) != 0 FROM pg_stat_monitor AS PGSM WHERE PGSM.query LIKE \'%INSERT INTO t1%\'', extra_params => ['-Pformat=unaligned','-Ptuples_only=on']);
trim($stdout);
is($stdout,'t',"Check: local_blk_write_time should not be 0.");
# Compare values for query 'SELECT * FROM t1' # Compare values for query 'SELECT * FROM t1'
($cmdret, $stdout, $stderr) = $node->psql('postgres', 'SELECT PGSM.local_blks_hit != 0 FROM pg_stat_monitor AS PGSM WHERE PGSM.query LIKE \'%FROM t1%\';', extra_params => ['-Pformat=unaligned','-Ptuples_only=on']); ($cmdret, $stdout, $stderr) = $node->psql('postgres', 'SELECT PGSM.local_blks_hit != 0 FROM pg_stat_monitor AS PGSM WHERE PGSM.query LIKE \'%FROM t1%\';', extra_params => ['-Pformat=unaligned','-Ptuples_only=on']);
trim($stdout); trim($stdout);
is($stdout,'t',"Check: shared_blks_hit should not be 0."); is($stdout,'t',"Check: local_blks_hit should not be 0.");
# TODO: Find a way how to bypass cache and ger real block reads
# ($cmdret, $stdout, $stderr) = $node->psql('postgres', 'SELECT SUM(PGSM.local_blk_read_time) != 0 FROM pg_stat_monitor AS PGSM WHERE PGSM.query LIKE \'%FROM t1%\';', extra_params => ['-Pformat=unaligned','-Ptuples_only=on']);
# trim($stdout);
# is($stdout,'t',"Check: local_blk_read_time should not be 0.");
# DROP EXTENSION # DROP EXTENSION
$stdout = $node->safe_psql('postgres', 'DROP EXTENSION pg_stat_monitor;', extra_params => ['-a']); $stdout = $node->safe_psql('postgres', 'DROP EXTENSION pg_stat_monitor;', extra_params => ['-a']);