[YSQL] Index backfill fails read point sanity check

[karthik-ramanathan-3006]

Jira Link: DB-20255

Description

Branch: master (as of 95e47f1)
Slack thread: https://yugabyte.slack.com/archives/C027M2T0W8Z/p1770328639014389

Index backfill runs into the following failure:

F20260203 18:19:10 ../../src/yb/tserver/pg_client_session.cc:1252] Check failed: read_time.read >= ipair.first->second.read_time().read

This can be reproduced by running the following test on a sanitizer build
(note that the test is currently disabled on sanitizer builds and has to be explicitly enabled)

./yb_build.sh asan --cxx-test pgwrapper_pg_index_backfill-test --gtest_filter 'PgIndexBackfillColumnProjectionTest.MultiColumnCompoundHash/1'

Stack trace:

F20260203 18:19:10 ../../src/yb/tserver/pg_client_session.cc:1252] Check failed: read_time.read >= ipair.first->second.read_time().read 
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/util/logging.cc:463:     @     0x7fc145cef04b  yb::LogFatalHandlerSink::send(int, char const*, char const*, int, tm const*, char const*, unsigned long)
    @     0x7fc144fbebb5 
    @     0x7fc144fabc85 
    @     0x7fc144faf7b2 
    @     0x7fc144fb6d3a 
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_session.cc:1252:     @     0x7fc152d9b6ca  yb::tserver::(anonymous namespace)::ReadPointHistory::Save(yb::ConsistentReadPoint const&, unsigned long)
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_session.cc:3225:     @     0x7fc152d9158a  yb::tserver::PgClientSession::Impl::DoPerform(yb::tserver::PgTablesQueryResult const&, shared_ptr<yb::tserver::(anonymous namespace)::QueryData<yb::tserver::(anonymous namespace)::QueryTraits<yb::tserver::PgPerformRequestPB, yb::tserver::PgPerformResponsePB>>> const&, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long long, std::ratio<1l, 1000000000l>>>, yb::rpc::RpcContext*)
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_session.cc:2627:     @     0x7fc152dc13b5  yb::tserver::PgClientSession::Impl::DoHandleSharedExchangeQuery(yb::LightweightFunction<yb::Status (unsigned long, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long long, std::ratio<1l, 1000000000l>>>)> const&, shared_ptr<yb::tserver::(anonymous namespace)::QueryData<yb::tserver::(anonymous namespace)::QueryTraits<yb::tserver::PgPerformRequestPB, yb::tserver::PgPerformResponsePB>>>&&, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long long, std::ratio<1l, 1000000000l>>>)
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_session.cc:2648:     @     0x7fc152dc13b5  yb::Status yb::tserver::PgClientSession::Impl::DoHandleSharedExchangeQuery<yb::tserver::(anonymous namespace)::QueryTraits<yb::tserver::PgPerformRequestPB, yb::tserver::PgPerformResponsePB>, yb::tserver::PgTableCache&>(yb::LightweightFunction<yb::Status (unsigned long, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long long, std::ratio<1l, 1000000000l>>>)> const&, yb::tserver::(anonymous namespace)::SharedExchangeQuery<yb::tserver::(anonymous namespace)::QueryTraits<yb::tserver::PgPerformRequestPB, yb::tserver::PgPerformResponsePB>>&, unsigned char*, unsigned long, unsigned long, int, yb::tserver::PgTableCache&)
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_session.cc:2657:     @     0x7fc152dc13b5  void yb::tserver::PgClientSession::Impl::HandleSharedExchangeQuery<yb::tserver::(anonymous namespace)::QueryTraits<yb::tserver::PgPerformRequestPB, yb::tserver::PgPerformResponsePB>, yb::tserver::PgTableCache&>(yb::LightweightFunction<yb::Status (unsigned long, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long long, std::ratio<1l, 1000000000l>>>)> const&, yb::tserver::SharedExchange&, unsigned char*, unsigned long, yb::tserver::PgTableCache&)
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_session.cc:2674:     @     0x7fc152dc13b5  yb::tserver::PgClientSession::Impl::ProcessSharedRequest(unsigned long, yb::tserver::SharedExchange*, yb::LightweightFunction<yb::Status (unsigned long, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long long, std::ratio<1l, 1000000000l>>>)> const&)
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/pg_client_service.cc:414:     @     0x7fc152c9854b  yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)::operator()(unsigned long) const
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__type_traits/invoke.h:87:     @     0x7fc152c9854b  std::__invoke_result_impl<void, yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long>::type std::__invoke[abi:ne210101]<yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long>(yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long&&)
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__type_traits/invoke.h:342:     @     0x7fc152c9854b  void std::__invoke_void_return_wrapper<void, true>::__call[abi:ne210101]<yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long>(yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long&&)
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__type_traits/invoke.h:348:     @     0x7fc152c9854b  void std::__invoke_r[abi:ne210101]<void, yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long>(yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long)&, unsigned long&&)
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__functional/function.h:174:     @     0x7fc152c9854b  std::__function::__func<yb::tserver::(anonymous namespace)::LockablePgClientSession::StartExchange(std::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, yb::YBThreadPool&)::'lambda'(unsigned long), void (unsigned long)>::operator()(unsigned long&&)
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__functional/function.h:274:     @     0x7fc14c96f726  std::__function::__value_func<void (unsigned long)>::operator()[abi:ne210101](unsigned long&&) const
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__functional/function.h:772:     @     0x7fc14c96f726  std::function<void (unsigned long)>::operator()(unsigned long) const
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/tserver/tserver_shared_mem.cc:492:     @     0x7fc14c96f726  yb::tserver::SharedExchangeRunnable::Run()
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/util/thread_pool.cc:168:     @     0x7fc145fe5381  yb::(anonymous namespace)::Worker::Execute(yb::ThreadPoolTask*)
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__functional/function.h:274:     @     0x7fc145fc153d  std::__function::__value_func<void ()>::operator()[abi:ne210101]() const
/opt/yb-build/thirdparty/yugabyte-db-thirdparty-v20251016191017-3fd3636b9a-almalinux9-x86_64-clang21/installed/asan/libcxx/include/c++/v1/__functional/function.h:772:     @     0x7fc145fc153d  std::function<void ()>::operator()() const
/share/jenkins/workspace/yugabyte-db-phabricator/yugabyte-db/build/asan-clang21-dynamic-ninja/../../src/yb/util/thread.cc:946:     @     0x7fc145fc153d  yb::Thread::SuperviseThread(void*)
/opt/yb-build/llvm/yb-llvm-v21.1.1-yb-1-1760067520-0e98b3b2-almalinux9-x86_64-build/src/llvm-project/compiler-rt/lib/asan/asan_interceptors.cpp:239:     @     0x56325b19fcd6  asan_thread_start
    @     0x7fc14208b2e9 
    @     0x7fc1421103bf 

Issue Type

kind/bug

Warning: Please confirm that this issue does not contain any sensitive information

• I confirm this issue does not contain any sensitive information.

[karthik-ramanathan-3006]

The sequence of operations leading to the failure is as follows:
(using pg_client_session.cc VLOG to illustrate)

The tserver receives a request to scan a portion of the main table as of a certain read_time. In this example, the read_time is { days: 20489 time: 21:47:29.561501 }

[ts-1] I0205 21:47:31.351600 3787770 pg_client_session.cc:3091] Session id 7 (pid 3787746):  Regular DML/ DDL op: txn_serial_no: 5, read_time_serial_no: 8; Read op: 000034d9000030008000000000004001;
..
[ts-1] I0205 21:47:31.352604 3787770 pg_client_session.cc:3189] vlog2: Session id 7 (pid 3787746): Performing RPC: pid=3787746, session_kind=kPlain, ops=[R:t], read_time={ read: { days: 20489 time: 21:47:29.561501 } local_limit: { days: 20489 time: 21:47:29.561501 } global_limit: { days: 20489 time: 21:47:29.561501 } in_txn_limit: { days: 20489 time: 21:47:31.333026 } serial_no: 0 }, read_time_serial_no=8, txn=none
..
[ts-1] I0205 21:47:31.353622 3787770 pg_client_session.cc:1238] vlog4: Session id 7 (pid 3787746): ReadPointHistory::Save read_time_serial_no=8 read time is { read: { days: 20489 time: 21:47:29.561501 } local_limit: { days: 20489 time: 21:47:29.561501 } global_limit: { days: 20489 time: 21:47:29.561501 } in_txn_limit: { days: 20489 time: 21:47:31.333026 } serial_no: 0 }

2. The tserver then receives a set of index rows to be written with no read time explicitly specified.

[ts-1] I0205 21:47:31.404220 3787770 pg_client_session.cc:3091] Session id 7 (pid 3787746):  Regular DML/ DDL op: txn_serial_no: 5, read_time_serial_no: 8; Write op: 000034d9000030008000000000004007;Write op: 000034d9000030008000000000004007; <other write ops on index table>
...
[ts-1] I0205 21:47:31.405001 3787770 pg_client_session.cc:3189] vlog2: Session id 7 (pid 3787746): Performing RPC: pid=3787746, session_kind=kPlain, ops=[W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx, W:idx], read_time=not set yet, read_time_serial_no=8, txn=none

3. However, a read time corresponding to Now() is saved onto the stack. In this example, this read_time is { days: 20489 time: 21:47:31.405700 }. Notice that this greater than the read_time used by the table scan for the backfill.

[ts-1] I0205 21:47:31.406802 3787770 pg_client_session.cc:3224] vlog3: Session id 7 (pid 3787746): Read time is already picked, saving it { read: { days: 20489 time: 21:47:31.405700 } local_limit: { days: 20489 time: 21:47:31.905700 } global_limit: { days: 20489 time: 21:47:31.905700 } in_txn_limit: <max> serial_no: 0 } to read time serial no: 8

4. The next table scan attempts to use the old read_time:

[ts-1] I0205 21:47:31.478569 3787770 pg_client_session.cc:3091] Session id 7 (pid 3787746):  Regular DML/ DDL op: txn_serial_no: 5, read_time_serial_no: 8; Read op: 000034d9000030008000000000004001;
..
[ts-1] I0205 21:47:31.479375 3787770 pg_client_session.cc:3189] vlog2: Session id 7 (pid 3787746): Performing RPC: pid=3787746, session_kind=kPlain, ops=[R:t], read_time={ read: { days: 20489 time: 21:47:29.561501 } local_limit: { days: 20489 time: 21:47:29.561501 } global_limit: { days: 20489 time: 21:47:29.561501 } in_txn_limit: { days: 20489 time: 21:47:31.333026 } serial_no: 0 }, read_time_serial_no=8, txn=none

5. When the table scan attempts to save the read_time on the stack, we get a "time going backwards" error:

[ts-1] I0205 21:47:31.480104 3787770 pg_client_session.cc:1238] vlog4: Session id 7 (pid 3787746): ReadPointHistory::Save read_time_serial_no=8 read time is { read: { days: 20489 time: 21:47:29.561501 } local_limit: { days: 20489 time: 21:47:29.561501 } global_limit: { days: 20489 time: 21:47:29.561501 } in_txn_limit: { days: 20489 time: 21:47:31.333026 } serial_no: 0 }
..
// this is my log message
[ts-1] I0205 21:47:31.480249 3787770 pg_client_session.cc:1252] read_time_serial_no: 8, given read point: { read: { days: 20489 time: 21:47:29.561501 } local_limit: { days: 20489 time: 21:47:29.561501 } global_limit: { days: 20489 time: 21:47:29.561501 } in_txn_limit: { days: 20489 time: 21:47:31.333026 } serial_no: 0 }, existing read point: { read: { days: 20489 time: 21:47:31.405700 } local_limit: { days: 20489 time: 21:47:31.905700 } global_limit: { days: 20489 time: 21:47:31.905700 } in_txn_limit: <max> serial_no: 0 }
..
[ts-1] F0205 21:47:31.480470 3787770 pg_client_session.cc:1253] Check failed: read_time.read >= ipair.first->second.read_time().read