Skip to content

Commit 36e3e30

Browse files
committed
[BACKPORT 2025.2][yugabyte#29080] YSQL: add debug log for relcache
Summary: The stacktrace of the core dump: ``` (lldb) bt all * thread #1, name = 'postgres', stop reason = signal SIGSEGV: address not mapped to object * frame #0: 0x0000aaaac59fb720 postgres`FreeTupleDesc [inlined] GetMemoryChunkContext(pointer=0x0000000000000000) at memutils.h:141:12 frame #1: 0x0000aaaac59fb710 postgres`FreeTupleDesc [inlined] pfree(pointer=0x0000000000000000) at mcxt.c:1500:26 frame #2: 0x0000aaaac59fb710 postgres`FreeTupleDesc(tupdesc=0x000013d7fd8dccc8) at tupdesc.c:326:5 frame #3: 0x0000aaaac61c7204 postgres`RelationDestroyRelation(relation=0x000013d7fd8dc9a8, remember_tupdesc=false) at relcache.c:4577:4 frame #4: 0x0000aaaac5febab8 postgres`YBRefreshCache at relcache.c:5216:3 frame #5: 0x0000aaaac5feba94 postgres`YBRefreshCache at postgres.c:4442:2 frame #6: 0x0000aaaac5feb50c postgres`YBRefreshCacheWrapperImpl(catalog_master_version=0, is_retry=false, full_refresh_allowed=true) at postgres.c:4570:3 frame #7: 0x0000aaaac5feea34 postgres`PostgresMain [inlined] YBRefreshCacheWrapper(catalog_master_version=0, is_retry=false) at postgres.c:4586:9 frame #8: 0x0000aaaac5feea2c postgres`PostgresMain [inlined] YBCheckSharedCatalogCacheVersion at postgres.c:4951:3 frame #9: 0x0000aaaac5fee984 postgres`PostgresMain(dbname=<unavailable>, username=<unavailable>) at postgres.c:6574:4 frame #10: 0x0000aaaac5efe5b4 postgres`BackendRun(port=0x000013d7ffc06400) at postmaster.c:4995:2 frame #11: 0x0000aaaac5efdd08 postgres`ServerLoop [inlined] BackendStartup(port=0x000013d7ffc06400) at postmaster.c:4701:3 frame #12: 0x0000aaaac5efdc70 postgres`ServerLoop at postmaster.c:1908:7 frame #13: 0x0000aaaac5ef8ef8 postgres`PostmasterMain(argc=<unavailable>, argv=<unavailable>) at postmaster.c:1562:11 frame #14: 0x0000aaaac5ddae1c postgres`PostgresServerProcessMain(argc=25, argv=0x000013d7ffe068f0) at main.c:213:3 frame #15: 0x0000aaaac59dee38 postgres`main + 36 frame #16: 0x0000ffff9f606340 libc.so.6`__libc_start_call_main + 112 frame #17: 0x0000ffff9f606418 libc.so.6`__libc_start_main@@GLIBC_2.34 + 152 frame #18: 0x0000aaaac59ded34 postgres`_start + 52 ``` It is related to invalidation message. The test involves concurrent DDL execution without object locking. I added a few logs to help to debug this issue. Original commit: 506e44e / D48114 Test Plan: (1) Append to the end of file ./build/latest/postgres/share/postgresql.conf.sample: ``` yb_debug_log_catcache_events=1 log_min_messages=DEBUG1 ``` (2) Create a RF-1 cluster ``` ./bin/yb-ctl create --rf 1 ``` (3) Run the following example via ysqlsh: ``` -- === 1. SETUP === DROP TABLE IF EXISTS accounts_timetravel; CREATE TABLE accounts_timetravel ( id INT PRIMARY KEY, balance INT, last_updated TIMESTAMPTZ ); INSERT INTO accounts_timetravel VALUES (1, 1000, now()); \echo '--- 1. Initial Data (The Past) ---' SELECT * FROM accounts_timetravel; -- Wait 2 seconds SELECT pg_sleep(2); -- === 2. CAPTURE THE "PAST" HLC TIMESTAMP === -- -- *** THIS IS THE FIX *** -- Get the current time as seconds from the Unix epoch, -- multiply by 1,000,000 to get microseconds, -- and cast to a big integer. -- SELECT (EXTRACT(EPOCH FROM now())*1000000)::bigint AS snapshot_hlc \gset SELECT :snapshot_hlc; \echo '--- (Snapshot HLC captured) ---' SELECT * FROM pg_yb_catalog_version; -- Wait 2 more seconds SELECT pg_sleep(2); -- === 3. UPDATE THE DATA === UPDATE accounts_timetravel SET balance = 500, last_updated = now() WHERE id = 1; \echo '--- 2. New Data (The Present) ---' SELECT * FROM accounts_timetravel; CREATE TABLE foo(id int); -- increment the catalog version ALTER TABLE foo ADD COLUMN val TEXT; SELECT * FROM pg_yb_catalog_version; -- === 4. PERFORM THE TIME-TRAVEL QUERY === -- -- Set our 'read_time_guc' variable to the HLC value -- \set read_time_guc :snapshot_hlc \echo '--- 3. Time-Travel Read (Querying the Past) ---' \echo 'Setting yb_read_time to HLC (microseconds):' :read_time_guc -- This will now be interpolated correctly and will succeed. SET yb_read_time = :read_time_guc; -- This query will now correctly read the historical data SELECT * FROM accounts_timetravel; SELECT * FROM pg_yb_catalog_version; -- === 5. CLEANUP === RESET yb_read_time; \echo '--- 4. Back to the Present ---' SELECT * FROM accounts_timetravel; DROP TABLE accounts_timetravel; ``` (4) Look at the postgres log for the following samples: ``` 2025-11-07 18:31:06.223 UTC [3321231] LOG: Preloading relcache for database 13524, session user id: 10, yb_read_time: 0 ``` ``` 2025-11-07 18:31:06.303 UTC [3321231] LOG: Building relcache entry for pg_index (oid 2610) took 785 us ``` ``` 2025-11-07 18:31:09.265 UTC [3321221] LOG: Rebuild relcache entry for accounts_timetravel (oid 16384) ``` ``` 2025-11-07 18:31:09.525 UTC [3321221] LOG: Delete relcache entry for accounts_timetravel (oid 16384) ``` ``` 2025-11-07 18:31:14.035 UTC [3321221] DEBUG: Setting yb_read_time to 1762540271568993 ``` ``` 2025-11-07 18:31:14.037 UTC [3321221] LOG: Preloading relcache for database 13524, session user id: 13523, yb_read_time: 1762540271568993 ``` ``` 2025-11-07 18:31:14.183 UTC [3321221] DEBUG: Setting yb_read_time to 0 ``` Reviewers: #db-approvers, kfranz Reviewed By: kfranz Subscribers: yql, jason Differential Revision: https://phorge.dev.yugabyte.com/D48216
1 parent fa6ea17 commit 36e3e30

2 files changed

Lines changed: 26 additions & 6 deletions

File tree

src/postgres/src/backend/utils/cache/relcache.c

Lines changed: 25 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -117,6 +117,7 @@
117117
#include "utils/relcache.h"
118118
#include "utils/yb_inheritscache.h"
119119
#include "utils/yb_tuplecache.h"
120+
#include "yb/yql/pggate/util/ybc_guc.h"
120121
#include "yb/yql/pggate/ybc_gflags.h"
121122
#include <inttypes.h>
122123

@@ -1561,6 +1562,9 @@ YBLoadRelations(YbUpdateRelationCacheState *state)
15611562
/* make sure relation is marked as having no open file yet */
15621563
relation->rd_smgr = NULL;
15631564

1565+
if (yb_debug_log_catcache_events)
1566+
elog(LOG, "Insert relcache entry %p for %s (oid %u)", relation,
1567+
RelationGetRelationName(relation), relid);
15641568
RelationCacheInsert(relation, true);
15651569

15661570
/* It's fully valid */
@@ -2970,9 +2974,12 @@ static YbcStatus
29702974
YbPreloadRelCacheImpl(YbRunWithPrefetcherContext *ctx)
29712975
{
29722976
YbNumRelCachePreloads++;
2973-
if (Log_connections || *(YBCGetGFlags()->ysql_enable_relcache_init_optimization))
2974-
elog(LOG, "Preloading relcache for database %u, session user id: %u",
2975-
MyDatabaseId, GetSessionUserId());
2977+
int log_level =
2978+
(Log_connections ||
2979+
yb_debug_log_catcache_events ||
2980+
*(YBCGetGFlags()->ysql_enable_relcache_init_optimization)) ? LOG : DEBUG1;
2981+
elog(log_level, "Preloading relcache for database %u, session user id: %u, yb_read_time: %" PRIu64,
2982+
MyDatabaseId, GetSessionUserId(), yb_read_time);
29762983

29772984
/*
29782985
* During relcache loading postgres reads the data from multiple sys tables.
@@ -3426,7 +3433,7 @@ RelationBuildDesc(Oid targetRelId, bool insertIt)
34263433

34273434
INSTR_TIME_SET_CURRENT(duration);
34283435
INSTR_TIME_SUBTRACT(duration, start);
3429-
elog(LOG, "Rebuilding relcache entry for %s (oid %d) took %ld us",
3436+
elog(LOG, "Building relcache entry %p for %s (oid %u) took %ld us", relation,
34303437
RelationGetRelationName(relation), RelationGetRelid(relation),
34313438
INSTR_TIME_GET_MICROSEC(duration));
34323439
}
@@ -4712,6 +4719,10 @@ RelationClearRelation(Relation relation, bool rebuild)
47124719
*/
47134720
if (!rebuild)
47144721
{
4722+
if (yb_debug_log_catcache_events)
4723+
elog(LOG, "Delete relcache entry %p for %s (oid %u)", relation,
4724+
RelationGetRelationName(relation), RelationGetRelid(relation));
4725+
47154726
/* Remove it from the hash table */
47164727
RelationCacheDelete(relation);
47174728

@@ -4815,6 +4826,10 @@ RelationClearRelation(Relation relation, bool rebuild)
48154826
elog(ERROR, "relation %u deleted while still in use", save_relid);
48164827
}
48174828

4829+
if (yb_debug_log_catcache_events)
4830+
elog(LOG, "Rebuild relcache entry %p for %s (oid %u)", relation,
4831+
RelationGetRelationName(relation), save_relid);
4832+
48184833
keep_tupdesc = equalTupleDescs(relation->rd_att, newrel->rd_att);
48194834
keep_rules = equalRuleLocks(relation->rd_rules, newrel->rd_rules);
48204835
keep_policies = equalRSDesc(relation->rd_rsdesc, newrel->rd_rsdesc);
@@ -9079,7 +9094,13 @@ load_relcache_init_file(bool shared, bool yb_retry)
90799094
for (relno = 0; relno < num_rels; relno++)
90809095
{
90819096
if (YBIsDBCatalogVersionMode())
9097+
{
9098+
Relation relation = rels[relno];
9099+
if (yb_debug_log_catcache_events)
9100+
elog(LOG, "Reinsert relcache entry %p for %s (oid %u)", relation,
9101+
RelationGetRelationName(relation), RelationGetRelid(relation));
90829102
YbRelationCacheReinsert(rels[relno], shared, yb_retry);
9103+
}
90839104
else
90849105
RelationCacheInsert(rels[relno], false);
90859106
}

src/postgres/src/backend/utils/misc/pg_yb_utils.c

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6805,6 +6805,7 @@ assign_yb_read_time(const char *newval, void *extra)
68056805
unsigned long long value_ull;
68066806
bool is_ht_unit;
68076807

6808+
elog(DEBUG1, "Setting yb_read_time to %s", newval);
68086809
parse_yb_read_time(newval, &value_ull, &is_ht_unit);
68096810
/*
68106811
* Don't refresh the sys caches in case the read time value didn't change.
@@ -7789,15 +7790,13 @@ YBCUpdateYbReadTimeAndInvalidateRelcache(uint64_t read_time_ht)
77897790
char read_time[50];
77907791

77917792
sprintf(read_time, "%llu ht", (unsigned long long) read_time_ht);
7792-
elog(DEBUG1, "Setting yb_read_time to %s ", read_time);
77937793
assign_yb_read_time(read_time, NULL);
77947794
YbRelationCacheInvalidate();
77957795
}
77967796

77977797
void
77987798
YBCResetYbReadTimeAndInvalidateRelcache()
77997799
{
7800-
elog(DEBUG1, "Setting yb_read_time to 0");
78017800
assign_yb_read_time("0", NULL);
78027801
YbRelationCacheInvalidate();
78037802
}

0 commit comments

Comments
 (0)