Skip to content

Debug #583

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 7 commits into
base: release-2.3.1
Choose a base branch
from
Draft

Debug #583

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
dfd2a7f
Add pg_stat_statements to EXTRA_INSTALL
artemgavrilov Nov 19, 2025
80c1f18
Debug
artemgavrilov Nov 19, 2025
7fa70fb
Disable optimizations
artemgavrilov Nov 20, 2025
c8cbf0f
Println debug
artemgavrilov Nov 20, 2025
1c18b0b
Revert "Println debug"
artemgavrilov Nov 20, 2025
13bc131
Reapply "Println debug"
artemgavrilov Nov 20, 2025
b6b88d2
Fix debug
artemgavrilov Nov 20, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion Makefile
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,10 +7,11 @@ EXTENSION = pg_stat_monitor
DATA = pg_stat_monitor--2.0.sql pg_stat_monitor--1.0--2.0.sql pg_stat_monitor--2.0--2.1.sql pg_stat_monitor--2.1--2.2.sql pg_stat_monitor--2.2--2.3.sql

PGFILEDESC = "pg_stat_monitor - execution statistics of SQL statements"

PG_CFLAGS += -O0 -g
LDFLAGS_SL += $(filter -lm, $(LIBS))

TAP_TESTS = 1
EXTRA_INSTALL = contrib/pg_stat_statements
REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/pg_stat_monitor/pg_stat_monitor.conf --inputdir=regression
REGRESS = basic \
version \
Expand Down
61 changes: 58 additions & 3 deletions pg_stat_monitor.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -283,6 +283,7 @@ static void pgsm_lock_release(pgsmSharedState *pgsm);
void
_PG_init(void)
{
printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
elog(DEBUG2, "[pg_stat_monitor] pg_stat_monitor: %s().", __FUNCTION__);

/*
Expand All @@ -296,22 +297,29 @@ _PG_init(void)
if (!process_shared_preload_libraries_in_progress)
return;

printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
/* Inilize the GUC variables */
init_guc();

printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
set_histogram_bucket_timings();

printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
#if PG_VERSION_NUM >= 140000

/*
* Inform the postmaster that we want to enable query_id calculation if
* compute_query_id is set to auto.
*/
printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
EnableQueryId();
printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
#endif

printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
EmitWarningsOnPlaceholders("pg_stat_monitor");

printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
/*
* Install hooks.
*/
Expand Down Expand Up @@ -342,6 +350,7 @@ _PG_init(void)
prev_ExecutorCheckPerms_hook = ExecutorCheckPerms_hook;
ExecutorCheckPerms_hook = HOOK(pgsm_ExecutorCheckPerms);

printf("pg_stat_monitor _PG_init: %d().\n", __LINE__);
nested_queryids = (int64 *) malloc(sizeof(int64) * max_stack_depth);
nested_query_txts = (char **) malloc(sizeof(char *) * max_stack_depth);

Expand All @@ -357,15 +366,19 @@ _PG_init(void)
void
pgsm_shmem_startup(void)
{
printf("pg_stat_monitor pgsm_shmem_startup: %d().\n", __LINE__);
if (prev_shmem_startup_hook)
prev_shmem_startup_hook();

printf("pg_stat_monitor pgsm_shmem_startup: %d().\n", __LINE__);
pgsm_startup();
printf("pg_stat_monitor pgsm_shmem_startup: %d().\n", __LINE__);
}

static void
request_additional_shared_resources(void)
{
printf("pg_stat_monitor request_additional_shared_resources: %d().\n", __LINE__);
/*
* Request additional shared resources. (These are no-ops if we're not in
* the postmaster process.) We'll allocate or attach to the shared
Expand All @@ -392,15 +405,19 @@ pg_stat_monitor_version(PG_FUNCTION_ARGS)
static void
pgsm_shmem_request(void)
{
printf("pg_stat_monitor pgsm_shmem_request: %d().\n", __LINE__);
if (prev_shmem_request_hook)
prev_shmem_request_hook();
printf("pg_stat_monitor pgsm_shmem_request: %d().\n", __LINE__);
request_additional_shared_resources();
printf("pg_stat_monitor pgsm_shmem_request: %d().\n", __LINE__);
}
#endif

static void
pgsm_post_parse_analyze_internal(ParseState *pstate, Query *query, JumbleState *jstate)
{
printf("pg_stat_monitor pgsm_post_parse_analyze_internal: %d().\n", __LINE__);
pgsmEntry *entry;
const char *query_text;
char *norm_query = NULL;
Expand All @@ -409,9 +426,11 @@ pgsm_post_parse_analyze_internal(ParseState *pstate, Query *query, JumbleState *
int query_len;

/* Safety check... */
printf("pg_stat_monitor pgsm_post_parse_analyze_internal: %d().\n", __LINE__);
if (!IsSystemInitialized())
return;

printf("pg_stat_monitor pgsm_post_parse_analyze_internal: %d().\n", __LINE__);
if (callback_setup == false)
{
/*
Expand All @@ -425,9 +444,11 @@ pgsm_post_parse_analyze_internal(ParseState *pstate, Query *query, JumbleState *
}
}

printf("pg_stat_monitor pgsm_post_parse_analyze_internal: %d().\n", __LINE__);
if (!pgsm_enabled(nesting_level))
return;

printf("pg_stat_monitor pgsm_post_parse_analyze_internal: %d().\n", __LINE__);
/*
* If it's EXECUTE, clear the queryId so that stats will accumulate for
* the underlying PREPARE. But don't do this if we're not tracking
Expand Down Expand Up @@ -609,7 +630,7 @@ pgsm_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count)
nested_queryids[nesting_level] = queryDesc->plannedstmt->queryId;
nested_query_txts[nesting_level] = strdup(queryDesc->sourceText);
}

printf("pg_stat_monitor pgsm_ExecutorRun: %d().\n", __LINE__);
nesting_level++;
PG_TRY();
{
Expand Down Expand Up @@ -651,6 +672,7 @@ pgsm_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count)
PG_RE_THROW();
}
PG_END_TRY();
printf("pg_stat_monitor pgsm_ExecutorRun: %d().\n", __LINE__);
}

/*
Expand All @@ -660,7 +682,7 @@ static void
pgsm_ExecutorFinish(QueryDesc *queryDesc)
{
nesting_level++;

printf("pg_stat_monitor pgsm_ExecutorFinish: %d().\n", __LINE__);
PG_TRY();
{
if (prev_ExecutorFinish)
Expand Down Expand Up @@ -710,6 +732,7 @@ pgsm_ExecutorEnd(QueryDesc *queryDesc)
PlanInfo *plan_ptr = NULL;
pgsmEntry *entry = NULL;

printf("pg_stat_monitor pgsm_ExecutorEnd: %d().\n", __LINE__);
/* Extract the plan information in case of SELECT statement */
if (queryDesc->operation == CMD_SELECT && pgsm_enable_query_plan)
{
Expand Down Expand Up @@ -739,6 +762,7 @@ pgsm_ExecutorEnd(QueryDesc *queryDesc)
MemoryContextSwitchTo(oldctx);
}

printf("pg_stat_monitor pgsm_ExecutorEnd: %d().\n", __LINE__);
if (queryId != INT64CONST(0) && queryDesc->totaltime && pgsm_enabled(nesting_level))
{
entry = pgsm_get_entry_for_query(queryId, plan_ptr, (char *) queryDesc->sourceText, strlen(queryDesc->sourceText), true, queryDesc->operation);
Expand Down Expand Up @@ -800,13 +824,14 @@ pgsm_ExecutorEnd(QueryDesc *queryDesc)
pgsm_store(entry);
}

printf("pg_stat_monitor pgsm_ExecutorEnd: %d().\n", __LINE__);
if (prev_ExecutorEnd)
prev_ExecutorEnd(queryDesc);
else
standard_ExecutorEnd(queryDesc);

pgsm_delete_entry(queryDesc->plannedstmt->queryId);

printf("pg_stat_monitor pgsm_ExecutorEnd: %d().\n", __LINE__);
num_relations = 0;
}

Expand Down Expand Up @@ -1046,13 +1071,15 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
int64 queryId = 0;
bool enabled = pgsm_track_utility && pgsm_enabled(nesting_level);

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
#if PG_VERSION_NUM < 140000
int len = strlen(queryString);

queryId = pgsm_hash_string(queryString, len);
#else
queryId = pstmt->queryId;

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
/*
* Force utility statements to get queryId zero. We do this even in cases
* where the statement contains an optimizable statement for which a
Expand All @@ -1066,6 +1093,7 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
pstmt->queryId = INT64CONST(0);
#endif

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
/*
* If it's an EXECUTE statement, we don't track it and don't increment the
* nesting level. This allows the cycles to be charged to the underlying
Expand Down Expand Up @@ -1105,6 +1133,7 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
INSTR_TIME_SET_CURRENT(start);
nesting_level++;

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
PG_TRY();
{
#if PG_VERSION_NUM >= 140000
Expand Down Expand Up @@ -1137,14 +1166,17 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
PG_CATCH();
{
nesting_level--;
printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
PG_RE_THROW();
}

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
sys_info.utime = 0;
sys_info.stime = 0;

PG_END_TRY();

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
if (getrusage(RUSAGE_SELF, &rusage_end) != 0)
elog(DEBUG1, "[pg_stat_monitor] pgsm_ProcessUtility: Failed to execute getrusage.");
else
Expand All @@ -1153,6 +1185,7 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
sys_info.stime = time_diff(rusage_end.ru_stime, rusage_start.ru_stime);
}

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
INSTR_TIME_SET_CURRENT(duration);
INSTR_TIME_SUBTRACT(duration, start);

Expand All @@ -1170,10 +1203,12 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
memset(&walusage, 0, sizeof(WalUsage));
WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start);

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
/* calc differences of buffer counters. */
memset(&bufusage, 0, sizeof(BufferUsage));
BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
/* Create an entry for this query */
entry = pgsm_create_hash_entry(0, queryId, NULL);

Expand All @@ -1184,11 +1219,13 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
entry->pgsm_query_id = get_pgsm_query_id_hash(query_text, query_len);
entry->counters.info.cmd_type = pstmt->commandType;

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
pgsm_add_to_list(entry, query_text, query_len);

/* Check that we've not exceeded max_stack_depth */
Assert(list_length(lentries) <= max_stack_depth);

printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
/* The plan details are captured when the query finishes */
pgsm_update_entry(entry, /* entry */
(char *) query_text, /* query */
Expand Down Expand Up @@ -1240,6 +1277,7 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
{
#endif
#if PG_VERSION_NUM >= 140000
printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
if (prev_ProcessUtility)
prev_ProcessUtility(pstmt, queryString,
readOnlyTree,
Expand Down Expand Up @@ -1277,7 +1315,9 @@ pgsm_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
PG_END_TRY();
#endif
}
printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
pgsm_delete_entry(pstmt->queryId);
printf("pg_stat_monitor pgsm_ProcessUtility: %d().\n", __LINE__);
}

/*
Expand Down Expand Up @@ -1401,6 +1441,7 @@ pgsm_update_entry(pgsmEntry *entry,
int sqlcode_len = error_info ? strlen(error_info->sqlcode) : 0;
int plan_text_len = plan_info ? plan_info->plan_len : 0;

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
/*
* Start collecting data for next bucket and reset all counters and
* timestamps
Expand All @@ -1412,9 +1453,11 @@ pgsm_update_entry(pgsmEntry *entry,
entry->minmax_stats_since = entry->stats_since;
}

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
if (kind == PGSM_STORE)
SpinLockAcquire(&entry->mutex);

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
/*
* Extract comments if enabled and only when the query has completed with
* or without error
Expand Down Expand Up @@ -1454,6 +1497,8 @@ pgsm_update_entry(pgsmEntry *entry,
}
}


printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
if (kind == PGSM_EXEC || kind == PGSM_STORE)
{
if (entry->counters.calls.calls == 0)
Expand Down Expand Up @@ -1487,6 +1532,7 @@ pgsm_update_entry(pgsmEntry *entry,
entry->counters.resp_calls[index]++;
}

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
if (plan_text_len > 0 && !entry->counters.planinfo.plan_text[0])
{
entry->counters.planinfo.planid = plan_info->planid;
Expand Down Expand Up @@ -1549,6 +1595,7 @@ pgsm_update_entry(pgsmEntry *entry,

entry->counters.calls.rows += rows;

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
if (bufusage)
{
entry->counters.blocks.shared_blks_hit += bufusage->shared_blks_hit;
Expand Down Expand Up @@ -1594,6 +1641,7 @@ pgsm_update_entry(pgsmEntry *entry,
#endif
}

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
entry->counters.calls.usage += USAGE_EXEC(exec_total_time + plan_total_time);

if (sys_info)
Expand Down Expand Up @@ -1647,6 +1695,7 @@ pgsm_update_entry(pgsmEntry *entry,
}
}

printf("pg_stat_monitor pgsm_update_entry: %d().\n", __LINE__);
/* parallel worker counters */
entry->counters.parallel_workers_to_launch += parallel_workers_to_launch;
entry->counters.parallel_workers_launched += parallel_workers_launched;
Expand Down Expand Up @@ -1695,12 +1744,14 @@ pgsm_add_to_list(pgsmEntry *entry, char *query_text, int query_len)
static void
pgsm_delete_entry(uint64 queryid)
{
printf("pg_stat_monitor pgsm_delete_entry: %d().\n", __LINE__);
pgsmEntry *entry = NULL;
ListCell *lc = NULL;

if (lentries == NIL)
return;

printf("pg_stat_monitor pgsm_delete_entry: %d().\n", __LINE__);
entry = (pgsmEntry *) llast(lentries);
if (entry->key.queryid == queryid)
{
Expand All @@ -1710,12 +1761,14 @@ pgsm_delete_entry(uint64 queryid)
return;
}

printf("pg_stat_monitor pgsm_delete_entry: %d().\n", __LINE__);
/*
* The rest of the code is just paranoia. In theory this list is a stack,
* and we always want to remove the last item. Similarly, in the getter
* method we are always looking for the last item.
*/

printf("pg_stat_monitor pgsm_delete_entry: %d().\n", __LINE__);
foreach(lc, lentries)
{
entry = lfirst(lc);
Expand All @@ -1724,9 +1777,11 @@ pgsm_delete_entry(uint64 queryid)
pfree(entry->query_text.query_pointer);
entry->query_text.query_pointer = NULL;
lentries = list_delete_cell(lentries, lc);
printf("pg_stat_monitor pgsm_delete_entry: %d().\n", __LINE__);
return;
}
}
printf("pg_stat_monitor pgsm_delete_entry: %d().\n", __LINE__);
}

static pgsmEntry *
Expand Down
2 changes: 2 additions & 0 deletions t/021_misc_1.pl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,8 @@
my ($cmdret, $stdout, $stderr) = $node->psql('postgres', 'CREATE EXTENSION pg_stat_monitor;', extra_params => ['-a']);
ok($cmdret == 0, "CREATE PGSM EXTENSION");
PGSM::append_to_file($stdout);
PGSM::append_to_debug_file($stderr);
PGSM::append_to_debug_file("-------------");

# Run required commands/queries and dump output to out file.

Expand Down
Loading
Loading