search

yugabyte / yugabyte-db

YugabyteDB - the cloud native distributed SQL database for mission-critical applications.
https://www.yugabyte.com
Other
8.68k stars 1.04k forks source link

[DocDB][Bulk Copy] Failed to write a batch with 0 operations into RocksDB: Corruption (yb/docdb/rocksdb_writer.cc:517): Unexpected write id. Expected: 762, found: 0, raw value: 0 vs 762 #14641

Open def- opened 1 year ago

def- commented 1 year ago

Jira Link: DB-4009

Description

While trying to load in data with 288 threads into a 6 node RF3 universe I am seeing this tserver fatal:

[yugabyte@ip ~]$ cat /home/yugabyte/tserver/logs/yb-tserver.FATAL.details.2022-10-24T12_20_46.pid5667.txt
F20221024 12:20:46 ../../src/yb/tablet/tablet.cc:1389] T 41d3bf148036439f9e620dd2806049e5 P 293ef1c6b994437197f43fa2702423cd: Failed to write a batch with 0 operations into RocksDB: Corruption (yb/docdb/rocksdb_writer.cc:517): Unexpected write id. Expected: 762, found: 0, raw value: 78F81143D89B4E45428404F24B8570A6B6770000000024: 0 vs 762
    @          0x2ab5048  google::LogMessage::SendToLog()
    @          0x2ab5f03  google::LogMessage::Flush()
    @          0x2ab63ff  google::LogMessageFatal::~LogMessageFatal()
    @          0x3648006  yb::tablet::Tablet::WriteToRocksDB()
    @          0x36445c8  yb::tablet::Tablet::ApplyIntents()
    @          0x3644f92  yb::tablet::Tablet::ApplyIntents()
    @          0x36f2e16  yb::tablet::TransactionParticipant::Impl::ProcessReplicated()
    @          0x368d982  yb::tablet::TabletBootstrap::PlayAnyRequest()
    @          0x368c43d  yb::tablet::TabletBootstrap::ApplyCommittedPendingReplicates()
    @          0x3684e10  yb::tablet::TabletBootstrap::PlaySegments()
    @          0x36793ea  yb::tablet::TabletBootstrap::Bootstrap()
    @          0x38abf1d  yb::tserver::TSTabletManager::OpenTablet()
    @          0x3bc9d91  yb::ThreadPool::DispatchThread()
    @          0x3bc5beb  yb::Thread::SuperviseThread()
    @     0x7fbc70f3d694  start_thread
    @     0x7fbc7143f41d  __clone

The tserver then never comes up again and stays in this corrupted state. The version is 2.17.1.41 with a preliminary fix by @spolitov for https://github.com/yugabyte/yugabyte-db/issues/14113 and https://github.com/yugabyte/yugabyte-db/issues/14109. Quoting Sergei:

I don’t think that it is related to the fix. Could be some other bug. Also it could be quite old bug, because we did not run this test before, and it is very stressful

The bulk copy is quite stressful indeed, universe was at ~80% CPU usage during it: Screenshot 2022-10-25 at 09-46-16 YugabyteDB Anywhere UI

Gflags: master: enable_load_balancing: false, txn_max_apply_batch_records: 400000 tserver: ysql_select_parallelism: -1, txn_max_apply_batch_records: 400000 The universe is in a paused state at https://portal.dev.yugabyte.com/universes/8e4b610e-68c0-4a75-915b-1fda0ee82bce. Tell me if you need any specific data from this universe, otherwise I will terminate it in a few days.

I will check if this can be reproduced on a new universe: https://portal.dev.yugabyte.com/universes/5c9cdee7-750d-47e9-8a2a-2ffe4a09e74a/tasks ![Screenshot 2022-10-25 at 09-58-32 YugabyteDB Anywhere UI](https://user-images.githubusercontent.com/2335377/197717401-551f9cc6-d022-4d82-949b-946408347383.png)

bulkcopyfile.py: https://gist.github.com/def-/ef86e5da7ca5c7172bd5f300bc6de027

python3 -u ./bulkcopyfile.py 288 35000 $ips | tee account-sergei4.log

account-sergei4.log

def- commented 1 year ago

Couldn't reproduce.

def- commented 1 year ago

The first tserver fatal that occurred was slight different than the follow-ups:

[yugabyte@ip-172-151-54-81 logs]$ cat yb-tserver.FATAL.details.2022-10-24T11_53_55.pid21684.txt
F20221024 11:53:55 ../../src/yb/tablet/tablet.cc:1389] T 41d3bf148036439f9e620dd2806049e5 P 293ef1c6b994437197f43fa2702423cd: Failed to write a batch with 0 operations into RocksDB: Corruption (yb/docdb/rocksdb_writer.cc:517): Unexpected write id. Expected: 762, found: 0, raw value: 78F81143D89B4E45428404F24B8570A6B6770000000024: 0 vs 762
    @          0x2ab5048  google::LogMessage::SendToLog()
    @          0x2ab5f03  google::LogMessage::Flush()
    @          0x2ab63ff  google::LogMessageFatal::~LogMessageFatal()
    @          0x3648006  yb::tablet::Tablet::WriteToRocksDB()
    @          0x36445c8  yb::tablet::Tablet::ApplyIntents()
    @          0x3644f92  yb::tablet::Tablet::ApplyIntents()
    @          0x36f2e16  yb::tablet::TransactionParticipant::Impl::ProcessReplicated()
    @          0x362aeae  yb::tablet::UpdateTxnOperation::DoReplicated()
    @          0x361f95f  yb::tablet::Operation::Replicated()
    @          0x3621534  yb::tablet::OperationDriver::ReplicationFinished()
    @          0x2eb2d25  yb::consensus::ConsensusRound::NotifyReplicationFinished()
    @          0x2efd8ab  yb::consensus::ReplicaState::ApplyPendingOperationsUnlocked()
    @          0x2efcca9  yb::consensus::ReplicaState::AdvanceCommittedOpIdUnlocked()
    @          0x2ee6617  yb::consensus::RaftConsensus::UpdateReplica()
    @          0x2ec9a84  yb::consensus::RaftConsensus::Update()
    @          0x388307d  yb::tserver::ConsensusServiceImpl::UpdateConsensus()
    @          0x2f399bb  std::__1::__function::__func<>::operator()()
    @          0x2f3a4b4  yb::consensus::ConsensusServiceIf::Handle()
    @          0x358cdd2  yb::rpc::ServicePoolImpl::Handle()
    @          0x34d21f3  yb::rpc::InboundCall::InboundCallTask::Run()
    @          0x359bba9  yb::rpc::(anonymous namespace)::Worker::Execute()
    @          0x3bc5beb  yb::Thread::SuperviseThread()
    @     0x7f00f62d5694  start_thread
    @     0x7f00f67d741d  __clone

Previous error logging on tserver:

E1024 11:50:01.578979  8857 consensus_queue.cc:738] T afbf036cfd764c8ea130e15d79f74fd8 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 60228 is ahead of the local log (next sequential op: 60228). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:01.783710 27346 tablet_metadata.cc:562] Failed to destroy regular DB at: /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e800003000800000000000400b/tablet-5fe4687d15684854a4a98e1463a6e960: IO error (yb/rocksdb/util/env_posix.cc:320): /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e800003000800000000000400b/tablet-5fe4687d15684854a4a98e1463a6e960/LOCK: No such file or directory
E1024 11:51:27.344442  8873 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:27.958142   732 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:28.378643  8900 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:28.792464  8925 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:29.273485  8816 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:29.818733  8857 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:30.401176  8835 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:30.879484  8849 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:31.267472   721 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:31.369463 32556 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
E1024 11:51:31.372615 32556 consensus_queue.cc:738] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd [LEADER]: Error trying to read ahead of the log while preparing peer request: Incomplete (yb/consensus/log_cache.cc:307): Op with index 62449 is ahead of the local log (next sequential op: 62449). Destination peer: 915dc59f483b4fcda628ceb979da5881
F1024 11:53:55.363430  8894 tablet.cc:1389] T 41d3bf148036439f9e620dd2806049e5 P 293ef1c6b994437197f43fa2702423cd: Failed to write a batch with 0 operations into RocksDB: Corruption (yb/docdb/rocksdb_writer.cc:517): Unexpected write id. Expected: 762, found: 0, raw value: 78F81143D89B4E45428404F24B8570A6B6770000000024: 0 vs 762

and for completeness also INFO logging:

I1024 11:53:55.012073 32548 log_cache.cc:419] T ba79854ab06440948ad0966bac4303cd P 293ef1c6b994437197f43fa2702423cd: Successfully read 3 ops from disk.
I1024 11:53:55.026597  8861 log_cache.cc:419] T 270576d824494ef0a12644a3d5dcb2e4 P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
W1024 11:53:55.052490  8917 yb_rpc.cc:400] Call yb.tserver.TabletServerService.UpdateTransaction 172.151.64.102:37417 => 172.151.54.81:9100 (request call id 22769619) took 13478ms (client timeout 3646ms).
I1024 11:53:55.053529  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:44675 => 172.151.54.81:9100 (request call id 26812590) took 13492ms. Trace:
I1024 11:53:55.054466  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:37849 => 172.151.54.81:9100 (request call id 26812572) took 13502ms. Trace:
I1024 11:53:55.055359  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:33784 => 172.151.54.81:9100 (request call id 26812538) took 13511ms. Trace:
I1024 11:53:55.056171  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:43459 => 172.151.54.81:9100 (request call id 26812578) took 13502ms. Trace:
I1024 11:53:55.057636  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.78.163:39600 => 172.151.54.81:9100 (request call id 20114937) took 13556ms. Trace:
I1024 11:53:55.059490  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:42672 => 172.151.54.81:9100 (request call id 26812522) took 13520ms. Trace:
I1024 11:53:55.059969 32548 log_cache.cc:419] T ba79854ab06440948ad0966bac4303cd P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
I1024 11:53:55.060896  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:39684 => 172.151.54.81:9100 (request call id 26812525) took 13511ms. Trace:
I1024 11:53:55.062757  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.64.102:40861 => 172.151.54.81:9100 (request call id 22769612) took 13488ms. Trace:
I1024 11:53:55.063470  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:36872 => 172.151.54.81:9100 (request call id 26812577) took 13510ms. Trace:
I1024 11:53:55.064232  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:44675 => 172.151.54.81:9100 (request call id 26812422) took 13552ms. Trace:
I1024 11:53:55.065037  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.78.163:36147 => 172.151.54.81:9100 (request call id 20114956) took 13552ms. Trace:
I1024 11:53:55.065927  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:37849 => 172.151.54.81:9100 (request call id 26812545) took 13517ms. Trace:
I1024 11:53:55.067097  8801 log_cache.cc:419] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd: Successfully read 2 ops from disk.
I1024 11:53:55.067363 32548 log_cache.cc:419] T ba79854ab06440948ad0966bac4303cd P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
I1024 11:53:55.079627 21840 log_cache.cc:419] T c8c65df4e75c4854898233da5535b27a P 293ef1c6b994437197f43fa2702423cd: Successfully read 3 ops from disk.
W1024 11:53:55.080932 21856 outbound_call.cc:365] RPC callback for RPC call yb.consensus.ConsensusService.UpdateConsensus -> { remote: 172.151.64.102:9100 idx: 2 protocol: 0x000000000458d318 -> tcpc } , state=FINISHED_SUCCESS. took 0.141s
I1024 11:53:55.081240  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:33784 => 172.151.54.81:9100 (request call id 26812587) took 13523ms. Trace:
I1024 11:53:55.083287  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.16.158:33005 => 172.151.54.81:9100 (request call id 4586670) took 13553ms. Trace:
I1024 11:53:55.085884  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:39684 => 172.151.54.81:9100 (request call id 26812543) took 13536ms. Trace:
I1024 11:53:55.087035  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:44675 => 172.151.54.81:9100 (request call id 26812539) took 13536ms. Trace:
I1024 11:53:55.090107  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:42371 => 172.151.54.81:9100 (request call id 26812551) took 13538ms. Trace:
I1024 11:53:55.091545  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:39684 => 172.151.54.81:9100 (request call id 26812591) took 13531ms. Trace:
I1024 11:53:55.093839  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:42672 => 172.151.54.81:9100 (request call id 26812553) took 13546ms. Trace:
I1024 11:53:55.096818  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.64.102:41510 => 172.151.54.81:9100 (request call id 22769529) took 13533ms. Trace:
I1024 11:53:55.097875  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:44675 => 172.151.54.81:9100 (request call id 26812566) took 13547ms. Trace:
I1024 11:53:55.108808 32548 log_cache.cc:419] T ba79854ab06440948ad0966bac4303cd P 293ef1c6b994437197f43fa2702423cd: Successfully read 4 ops from disk.
I1024 11:53:55.110847 24683 service_util.cc:397] Rejecting Write request: Soft memory limit exceeded for root (at 87.36% of capacity), score: 0.00 [suppressed 27 similar messages]
I1024 11:53:55.144942 16087 log_cache.cc:419] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
I1024 11:53:55.149907 21894 flush_job.cc:311] T ff7210c72e1d48e886377850c90acf4b P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 337] Level-0 flush table #819: 3920735 bytes OK frontiers: { smallest: { op_id: 4.69251 hybrid_time: { physical: 1666612397673489 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: <NULL> cotable_schema_versions: [] } largest: { op_id: 4.69321 hybrid_time: { physical: 1666612426423197 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: <NULL> cotable_schema_versions: [] } }
I1024 11:53:55.149951 21894 event_logger.cc:66] T ff7210c72e1d48e886377850c90acf4b P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435149929, "cf_name": "default", "job": 337, "event": "table_file_creation", "file_number": 819, "file_size": 3920735, "table_properties": {"data_size": 3851224, "data_index_size": 9821, "filter_size": 65482, "filter_index_size": 22, "raw_key_size": 6431933, "raw_average_key_size": 113, "raw_value_size": 775283, "raw_average_value_size": 13, "num_data_blocks": 169, "num_entries": 56433, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyV3Filter", "kDeletedKeys": "0"}}
I1024 11:53:55.151743 21896 flush_job.cc:311] T caf02f5205c44046ab6f8243bde4a53f P 293ef1c6b994437197f43fa2702423cd [I]: [default] [JOB 657] Level-0 flush table #585: 15526891 bytes OK frontiers: { smallest: { op_id: 5.74519 hybrid_time: { physical: 1666612382812629 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: 0x0000000081995f48 -> 0 cotable_schema_versions: [] } largest: { op_id: 5.74623 hybrid_time: { physical: 1666612422256147 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <initial> primary_schema_version: 0x0000000466c59928 -> 0 cotable_schema_versions: [] } }
I1024 11:53:55.151774 21896 event_logger.cc:66] T caf02f5205c44046ab6f8243bde4a53f P 293ef1c6b994437197f43fa2702423cd [I]: EVENT_LOG_v1 {"time_micros": 1666612435151763, "cf_name": "default", "job": 657, "event": "table_file_creation", "file_number": 585, "file_size": 15526891, "table_properties": {"data_size": 15229080, "data_index_size": 65810, "filter_size": 261928, "filter_index_size": 151, "raw_key_size": 28785555, "raw_average_key_size": 76, "raw_value_size": 14804078, "raw_average_value_size": 39, "num_data_blocks": 881, "num_entries": 377330, "num_filter_blocks": 4, "num_data_index_blocks": 4, "filter_policy_name": "DocKeyV3Filter", "kDeletedKeys": "143705"}}
W1024 11:53:55.160378  8861 outbound_call.cc:365] RPC callback for RPC call yb.consensus.ConsensusService.UpdateConsensus -> { remote: 172.151.64.102:9100 idx: 4 protocol: 0x000000000458d318 -> tcpc } , state=FINISHED_SUCCESS. took 1.217s
I1024 11:53:55.161676 21894 memtable_list.cc:385] T ff7210c72e1d48e886377850c90acf4b P 293ef1c6b994437197f43fa2702423cd [R]: [default] Level-0 commit table #819 started
I1024 11:53:55.161695 21894 memtable_list.cc:401] T ff7210c72e1d48e886377850c90acf4b P 293ef1c6b994437197f43fa2702423cd [R]: [default] Level-0 commit table #819: memtable #1 done
I1024 11:53:55.161700 21894 event_logger.cc:76] T ff7210c72e1d48e886377850c90acf4b P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435161243, "job": 337, "event": "flush_finished", "lsm_state": [6]}
I1024 11:53:55.168335 21896 memtable_list.cc:385] T caf02f5205c44046ab6f8243bde4a53f P 293ef1c6b994437197f43fa2702423cd [I]: [default] Level-0 commit table #585 started
I1024 11:53:55.168354 21896 memtable_list.cc:401] T caf02f5205c44046ab6f8243bde4a53f P 293ef1c6b994437197f43fa2702423cd [I]: [default] Level-0 commit table #585: memtable #1 done
I1024 11:53:55.168360 21896 event_logger.cc:76] T caf02f5205c44046ab6f8243bde4a53f P 293ef1c6b994437197f43fa2702423cd [I]: EVENT_LOG_v1 {"time_micros": 1666612435167984, "job": 657, "event": "flush_finished", "lsm_state": [4]}
I1024 11:53:55.168951 32548 log_cache.cc:419] T ba79854ab06440948ad0966bac4303cd P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
I1024 11:53:55.171401 21896 flush_job.cc:251] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 36] Flushing memtable with next log file: 1004
I1024 11:53:55.171440 21896 event_logger.cc:66] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435171434, "job": 36, "event": "flush_started", "num_memtables": 1, "num_entries": 31939, "num_deletes": 0, "memory_usage": 5972344}
I1024 11:53:55.171447 21896 flush_job.cc:279] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 36] Level-0 flush table #1044: started
I1024 11:53:55.184515 21894 flush_job.cc:251] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: [default] [JOB 324] Flushing memtable with next log file: 3
I1024 11:53:55.184546 21894 event_logger.cc:66] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: EVENT_LOG_v1 {"time_micros": 1666612435184539, "job": 324, "event": "flush_started", "num_memtables": 1, "num_entries": 11, "num_deletes": 0, "memory_usage": 968}
I1024 11:53:55.184552 21894 flush_job.cc:279] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: [default] [JOB 324] Level-0 flush table #171: started
W1024 11:53:55.184579 21894 env.cc:90] Failed to cleanup /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e9000030008000000000004000/tablet-8a653493115e4ed99e6255fb7cce3053.intents/000171.sst: IO error (yb/rocksdb/util/env_posix.cc:241): /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e9000030008000000000004000/tablet-8a653493115e4ed99e6255fb7cce3053.intents/000171.sst: No such file or directory
W1024 11:53:55.184602 21894 env.cc:90] Failed to cleanup /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e9000030008000000000004000/tablet-8a653493115e4ed99e6255fb7cce3053.intents/000171.sst.sblock.0: IO error (yb/rocksdb/util/env_posix.cc:241): /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e9000030008000000000004000/tablet-8a653493115e4ed99e6255fb7cce3053.intents/000171.sst.sblock.0: No such file or directory
I1024 11:53:55.184628 21894 flush_job.cc:311] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: [default] [JOB 324] Level-0 flush table #171: 0 bytes OK frontiers: { smallest: { op_id: 1.803 hybrid_time: { physical: 1666612384621982 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: 0x00000000a95f0b98 -> 0 cotable_schema_versions: [] } largest: { op_id: 1.805 hybrid_time: { physical: 1666612384819379 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <initial> primary_schema_version: 0x0000000052b090d8 -> 0 cotable_schema_versions: [] } }
I1024 11:53:55.184659 21894 event_logger.cc:66] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: EVENT_LOG_v1 {"time_micros": 1666612435184635, "cf_name": "default", "job": 324, "event": "table_file_creation", "file_number": 171, "file_size": 0, "table_properties": {"data_size": 0, "data_index_size": 0, "filter_size": 0, "filter_index_size": 0, "raw_key_size": 0, "raw_average_key_size": 0, "raw_value_size": 0, "raw_average_value_size": 0, "num_data_blocks": 0, "num_entries": 0, "num_filter_blocks": 0, "num_data_index_blocks": 0, "filter_policy_name": ""}}
I1024 11:53:55.192837 21894 memtable_list.cc:385] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: [default] Level-0 commit table #171 started
I1024 11:53:55.192858 21894 memtable_list.cc:401] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: [default] Level-0 commit table #171: memtable #1 done
I1024 11:53:55.192863 21894 event_logger.cc:76] T 8a653493115e4ed99e6255fb7cce3053 P 293ef1c6b994437197f43fa2702423cd [I]: EVENT_LOG_v1 {"time_micros": 1666612435192536, "job": 324, "event": "flush_finished", "lsm_state": [0]}
I1024 11:53:55.206255  8801 log_cache.cc:419] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
W1024 11:53:55.235597 32548 outbound_call.cc:365] RPC callback for RPC call yb.consensus.ConsensusService.UpdateConsensus -> { remote: 172.151.64.102:9100 idx: 3 protocol: 0x000000000458d318 -> tcpc } , state=FINISHED_SUCCESS. took 0.451s
I1024 11:53:55.312041 21896 flush_job.cc:311] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 36] Level-0 flush table #1044: 1336996 bytes OK frontiers: { smallest: { op_id: 8.685997 hybrid_time: { physical: 1666612401575617 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: <NULL> cotable_schema_versions: [] } largest: { op_id: 8.687397 hybrid_time: { physical: 1666612429940220 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: <NULL> cotable_schema_versions: [] } }
I1024 11:53:55.312081 21896 event_logger.cc:66] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435312065, "cf_name": "default", "job": 36, "event": "table_file_creation", "file_number": 1044, "file_size": 1336996, "table_properties": {"data_size": 1263025, "data_index_size": 8789, "filter_size": 65482, "filter_index_size": 22, "raw_key_size": 5060418, "raw_average_key_size": 158, "raw_value_size": 413667, "raw_average_value_size": 12, "num_data_blocks": 125, "num_entries": 31939, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyV3Filter", "kDeletedKeys": "0"}}
I1024 11:53:55.314361 21896 compaction_picker.cc:1780] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Universal: Picking file 1044[0] with size 1336996 (compensated size 1336996)
I1024 11:53:55.314378 21896 compaction_picker.cc:1780] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Universal: Picking file 1043[1] with size 642439 (compensated size 642439)
I1024 11:53:55.314385 21896 compaction_picker.cc:1780] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Universal: Picking file 1042[2] with size 1271266 (compensated size 1271266)
I1024 11:53:55.314390 21896 compaction_picker.cc:1780] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Universal: Picking file 1041[3] with size 14569799 (compensated size 14569799)
I1024 11:53:55.314396 21896 compaction_picker.cc:1481] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Universal: compacting for size ratio
I1024 11:53:55.314409 21896 db_impl.cc:1959] [default] Level summary: files[5] max score 1.00
I1024 11:53:55.314504 21896 memtable_list.cc:385] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Level-0 commit table #1044 started
I1024 11:53:55.314512 21896 memtable_list.cc:401] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: [default] Level-0 commit table #1044: memtable #1 done
I1024 11:53:55.314517 21896 event_logger.cc:76] T d1febc95356243c8a59c62fdc4f57ffd P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435314035, "job": 36, "event": "flush_finished", "lsm_state": [5]}
I1024 11:53:55.314697 21896 db_impl.cc:3320] T 2db54365df4b4d7d91ecd10942ed00fc P 293ef1c6b994437197f43fa2702423cd [I]: Calling FlushMemTableToOutputFile with column family [default], flush slots scheduled 1, total flush slots 3, compaction slots scheduled 0, compaction tasks [], total compaction slots 3
I1024 11:53:55.314723 21896 db_impl.cc:5463] T 2db54365df4b4d7d91ecd10942ed00fc P 293ef1c6b994437197f43fa2702423cd [R]: [default] New memtable created with log file: #468
I1024 11:53:55.314955 21896 flush_job.cc:151] T 2db54365df4b4d7d91ecd10942ed00fc P 293ef1c6b994437197f43fa2702423cd [I]: [default] No eligible memtables to flush.
I1024 11:53:55.326301 21896 db_impl.cc:5463] T 9fa76db47325465e9f10bd522803396a P 293ef1c6b994437197f43fa2702423cd [R]: [default] New memtable created with log file: #881
I1024 11:53:55.336879 21896 db_impl.cc:5463] T 1c4d3caae17a4250b20501406c23c078 P 293ef1c6b994437197f43fa2702423cd [R]: [default] New memtable created with log file: #907
I1024 11:53:55.348171 21896 flush_job.cc:251] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 503] Flushing memtable with next log file: 580
I1024 11:53:55.348203 21896 event_logger.cc:66] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435348195, "job": 503, "event": "flush_started", "num_memtables": 1, "num_entries": 2704, "num_deletes": 0, "memory_usage": 350824}
I1024 11:53:55.348210 21896 flush_job.cc:279] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 503] Level-0 flush table #1087: started
I1024 11:53:55.350575 21840 log_cache.cc:419] T c8c65df4e75c4854898233da5535b27a P 293ef1c6b994437197f43fa2702423cd: Successfully read 2 ops from disk.
I1024 11:53:55.355130  8801 log_cache.cc:419] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
I1024 11:53:55.360098 21896 flush_job.cc:311] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: [default] [JOB 503] Level-0 flush table #1087: 107976 bytes OK frontiers: { smallest: { op_id: 13.61885 hybrid_time: { physical: 1666612393979677 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: <NULL> cotable_schema_versions: [] } largest: { op_id: 13.61987 hybrid_time: { physical: 1666612427533722 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: <NULL> cotable_schema_versions: [] } }
I1024 11:53:55.360131 21896 event_logger.cc:66] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435360116, "cf_name": "default", "job": 503, "event": "table_file_creation", "file_number": 1087, "file_size": 107976, "table_properties": {"data_size": 41318, "data_index_size": 295, "filter_size": 65482, "filter_index_size": 22, "raw_key_size": 243694, "raw_average_key_size": 90, "raw_value_size": 54147, "raw_average_value_size": 20, "num_data_blocks": 4, "num_entries": 2704, "num_filter_blocks": 1, "num_data_index_blocks": 1, "filter_policy_name": "DocKeyV3Filter", "kDeletedKeys": "0"}}
F1024 11:53:55.363430  8894 tablet.cc:1389] T 41d3bf148036439f9e620dd2806049e5 P 293ef1c6b994437197f43fa2702423cd: Failed to write a batch with 0 operations into RocksDB: Corruption (yb/docdb/rocksdb_writer.cc:517): Unexpected write id. Expected: 762, found: 0, raw value: 78F81143D89B4E45428404F24B8570A6B6770000000024: 0 vs 762
I1024 11:53:55.442847  8801 log_cache.cc:419] T ff72e9aa05eb4623a99122d6aa32b3d3 P 293ef1c6b994437197f43fa2702423cd: Successfully read 1 ops from disk.
I1024 11:53:55.363970 24788 yb_rpc.cc:413] Call yb.tserver.PgClientService.Perform 172.151.54.81:58588 => 172.151.54.81:9100 (request call id 746) took 30806ms. Trace:
I1024 11:53:55.365226 21896 memtable_list.cc:385] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: [default] Level-0 commit table #1087 started
I1024 11:53:55.452842 21896 memtable_list.cc:401] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: [default] Level-0 commit table #1087: memtable #1 done
I1024 11:53:55.452854 21896 event_logger.cc:76] T 2206a544f1894a2eb432082726af0ead P 293ef1c6b994437197f43fa2702423cd [R]: EVENT_LOG_v1 {"time_micros": 1666612435364806, "job": 503, "event": "flush_finished", "lsm_state": [5]}
I1024 11:53:55.452905 21896 flush_job.cc:251] T 70dd6cc9ed1b4105a44ca4738fdebb3b P 293ef1c6b994437197f43fa2702423cd [I]: [default] [JOB 478] Flushing memtable with next log file: 412
I1024 11:53:55.452934 21896 event_logger.cc:66] T 70dd6cc9ed1b4105a44ca4738fdebb3b P 293ef1c6b994437197f43fa2702423cd [I]: EVENT_LOG_v1 {"time_micros": 1666612435452917, "job": 478, "event": "flush_started", "num_memtables": 1, "num_entries": 423530, "num_deletes": 0, "memory_usage": 52369688}
I1024 11:53:55.452945 21896 flush_job.cc:279] T 70dd6cc9ed1b4105a44ca4738fdebb3b P 293ef1c6b994437197f43fa2702423cd [I]: [default] [JOB 478] Level-0 flush table #569: started
I1024 11:53:55.382071  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.61.213:44675 => 172.151.54.81:9100 (request call id 26812524) took 13831ms. Trace:
I1024 11:53:55.460992 21750 db_impl.cc:5463] T 3532bbbfad644c11918ae6a90603dda6 P 293ef1c6b994437197f43fa2702423cd [R]: [default] New memtable created with log file: #489
W1024 11:53:55.461053  7325 long_operation_tracker.cc:146] UpdateReplica took a long time: 2.558s
I1024 11:53:55.461135  8917 yb_rpc.cc:413] Call yb.tserver.TabletServerService.Write 172.151.64.102:40861 => 172.151.54.81:9100 (request call id 22769629) took 13883ms. Trace:
I1024 11:53:55.461318 21750 tablet_memory_manager.cc:289] Memstore global limit of 2147483648 bytes reached, looking for tablet to flush
W1024 11:53:55.464203  7325 yb_rpc.cc:400] Call yb.consensus.ConsensusService.UpdateConsensus 172.151.64.102:40861 => 172.151.54.81:9100 (request call id 22795706) took 2561ms (client timeout 3000ms).

Full logs collected, is it ok to terminate the universe now? https://drive.google.com/file/d/1927MfN2-whrFKgg0zk7NBCceQnvN7mWM/view?usp=sharing

def- commented 1 year ago

@bmatican See the previous message for what happened to cause this failure. I checked and there was no related coredump or crash before that. I'm running the test again to see if it reproduces.

Huqicheng commented 1 year ago

Raw value is: 78F81143D89B4E45428404F24B8570A6B6770000000024

<=>

78(x) F81143D89B4E45428404F24B8570A6B6 - transaction id 77(w) 00000000 - write id 24

Huqicheng commented 1 year ago

Dumped the intent db, max write id 761, min_write_id 530

Can find the last intent of this transaction is

TransactionId F81143D89B4E45428404F24B8570A6B6, WriteId 761 intent key: SubDocKey(DocKey(0x9876, ["13jraZBE5xA2yNmZnzFq4Qzd9b1Bvjzczqv4A7D9PEEcvryR5nS"], [EncodedSubDocKey(DocKey(0xef7f, [1370991], ["13jraZBE5xA2yNmZnzFq4Qzd9b1Bvjzczqv4A7D9PEEcvryR5nS"]), [])]), [SystemColumnId(0)]) [kStrongRead, kStrongWrite] HT{ physical: 1666612048313369 w: 32 }

right before writeId 762

Also can't find value 78F81143D89B4E45428404F24B8570A6B6770000000024 in intentdb with key_type == KeyType::kIntentKey

Huqicheng commented 1 year ago

id { term: 12 index: 663512 } hybrid_time: 6826443016563269632 op_type: WRITE_OP write { unused_tablet_id: "" write_batch { write_pairs { key: "G\2310S13qaohxRi7L2iJw9P5ybAcHTeahKrVxc6H8xb3ttuXPgYCnG6B3\000\000!SG\357\177I\ 200\000\001\000\001\000\001\000\001\024\353o!S13qaohxRi7L2iJw9P5ybAcHTeahKrVxc6H8xb3ttuXPgYCnG6B3\000\001\000\001!\000\000!J\200" value: "$" } write_pairs { key: "G\232wS147QRAVJB12sZumcj8UndBpMcpaxza5gWPhfPY5o7L1HQRYG6kg\000\000!SG\357\17 7I\200\000\001\000\001\000\001\000\001\024\353o!S147QRAVJB12sZumcj8UndBpMcpaxza5gWPhfPY5o7L1HQRYG6kg\000\001\000\001!\000\000!J\200" value: "$" } write_pairs { key: "G\230\366S14bVxE2QPm53r44L5yWtuebv5QuX66jL5279ZSZEdKkuoEkoPg1\000\000!SG\ 357\177I\200\000\001\000\001\000\001\000\001\024\353o!S14bVxE2QPm53r44L5yWtuebv5QuX66jL5279ZSZEdKkuoEkoPg1\000\001\000\001!\000\000!J\200" value: "$" } write_pairs { key: "G\232\341S138SmWBjQgSSMbzC6wfkQXsr2ncfAvwDN9AibdG5zdDyduh2UV4\000\0 00!SG\357\177I\200\000\001\000\001\000\001\000\001\024\353o!S138SmWBjQgSSMbzC6wfkQXsr2ncfAvwDN9AibdG5zdDyduh2UV4\000\001\000\001!\000\000!J\200" value: "$" } write_pairs { key: "G\231\274S14e72CvafZ4p3ussqvHRF2JdihyCa9r1yTHecnutMFViJEdFe5r \000\000!SG\357\177I\200\000\001\000\001\000\001\000\001\024\353o!S14e72CvafZ4p3ussqvHRF2JdihyCa9r1yTHecnutMFViJEdFe5r\000\001\000\001!\000\000!J\200" value: "$" } write_pairs { key: "G\230pS143WGgAgE6vXtbJmrr2d29SAASZ5qBV4vQLZeVPq2kgyhRrg yBt\000\000!SG\357\177I\200\000\001\000\001\000\001\000\001\024\353o!S143WGgAgE6vXtbJmrr2d29SAASZ5qBV4vQLZeVPq2kgyhRrgyBt\000\001\000\001!\000\000!J\200" value: "$" } transaction { transaction_id: "\370\021C\330\233NEB\204\004\362K\205p\24 6\266" isolation: SNAPSHOT_ISOLATION status_tablet: "3126b7ad4c1a44ba87369c5bf097a842" priority: 16603808568954923296 start_hybrid_time: 6826442569775816704 locality: GLOBAL } DEPRECATED_may_have_metadata: true table_schema_version { schem a_version: 0 } table_schema_version { schema_version: 0 } table_schema_version { schema_version: 0 } table_schema_version { schema_version: 0 } table_schema_version { schema_version: 0 } table_schema_version { schemaversion: 0 } } client id1: 8236005072640866197 client_id2: 739011930656885393 request_id: 16796016 min_running_request_id: 16796001 batch_idx: 0 } committed_op_id { term: 12 index: 663466 } monotonic_counter: 0

The write op containing write 762

Huqicheng commented 1 year ago

WriteId 761 write_pairs { key: "G\230vS13jraZBE5xA2yNmZnzFq4Qzd9b1Bvjzczqv4A7D9PEEcvryR5nS\000\000!SG\357\177I\200\000\001\000\001\000\001\000\001\024\353o!S13jraZBE5xA2yNmZnzFq4Qzd9b1Bvjz czqv4A7D9PEEcvryR5nS\000\001\000\001!\000\000!J\200" value: "$" }

Huqicheng commented 1 year ago

Seems the intra_txn_writeid restart from 0

Huqicheng commented 1 year ago

The issue is that when applying intents, write_id encoded in intent value becomes 0 in middle: 0, 1, 2, ..., 761, 0, 1, ..., 5 In one transaction, the intra_txn_writeid should be monotonically increasing.

Adding some logs in AddIntent, seeing the following intents added to intentdb during local bootstrap:

I1122 21:41:57.318341 19018 rocksdb_writer.cc:87] add intent value 78F81143D89B4E45428404F24B8570A6B6770000000024
 3820 I1122 21:41:57.318380 19018 rocksdb_writer.cc:87] add intent value 78F81143D89B4E45428404F24B8570A6B6770000000124
 3821 I1122 21:41:57.318406 19018 rocksdb_writer.cc:87] add intent value 78F81143D89B4E45428404F24B8570A6B6770000000224
 3822 I1122 21:41:57.318431 19018 rocksdb_writer.cc:87] add intent value 78F81143D89B4E45428404F24B8570A6B6770000000324
 3823 I1122 21:41:57.318455 19018 rocksdb_writer.cc:87] add intent value 78F81143D89B4E45428404F24B8570A6B6770000000424
 3824 I1122 21:41:57.318481 19018 rocksdb_writer.cc:87] add intent value 78F81143D89B4E45428404F24B8570A6B6770000000524

Intent with write id 0 was added because for this transaction next_write_id is 0 (expected 762) during local bootstrap

next_write_id is 0 for txn F81143D89B4E45428404F24B8570A6B6 because the transaction metadata for transaction F81143D89B4E45428404F24B8570A6B6 is missing in intentdb. The transaction is skipped when transaction participant doing LoadTransactions.

if (key.empty()) { // The key only contains a transaction id - it is metadata record.
        if (FLAGS_TEST_inject_load_transaction_delay_ms > 0) {
          std::this_thread::sleep_for(FLAGS_TEST_inject_load_transaction_delay_ms * 1ms);
        }
        LoadTransaction(id);
        ++loaded_transactions;
}

Question: Is it possible that transaction metadata could be cleaned before intents are all applied?

Update: The ops for this transaction is split into two WAL segments, and there's term change (caused by tablet split) between earlier ops and the last 3 ops (1 write op and 2 update txn ops)

Huqicheng commented 1 year ago 
 T 71288a08942a4f9c81c4e95700a78472 P 293ef1c6b994437197f43fa2702423cd: DoCleanupIntentFiles: Intents SST file will be deleted: { total_size: 34981462 base_size: 813725 uncompressed_size: 173745042 name_id: 1045 db_path: /mnt/d0/yb-data/tserver/data/rocksdb/table-000033e8000030008000000000004016/tablet-71288a08942a4f9c81c4e95700a78472.intents imported: 0 being_compacted: 0 column_family_name: default level: 0 smallest: { seqno: 0 user_frontier: 0x000000006b708700 -> { op_id: 1.28481 hybrid_time: { physical: 1666599791819427 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <invalid> primary_schema_version: 0x000000006b708738 -> 0 cotable_schema_versions: [] } } largest: { seqno: 1125900566862459 user_frontier: 0x0000000078d0d3b0 -> { op_id: 11.661770 hybrid_time: { physical: 1666612021281704 } history_cutoff: <invalid> hybrid_time_filter: <invalid> max_value_level_ttl_expiration_time: <initial> primary_schema_version: 0x0000000078d0d3e8 -> 0 cotable_schema_versions: [] } } }, max ht: { physical: 1666612021281704 }, min running transaction start ht: { physical: 1666612037350647 }
截屏2022-11-24 下午12 19 40

The intent file has data up to 1666612021281704 == 2022-10-24 11:47:01 And op id range is 1.28481 -> 11.661770

Last op of this transaction has timestamp 1666612012164862 == 2022-10-24 11:46:52 Min running transaction start ht is 1666612037350647 == 2022-10-24 11:47:17

rthallamko3 commented 1 year ago

Not a 2.16.0 blocker as the odds of it happening are very low. The transaction needs to have committed a while ago, and then the apply of its intents can run into the above issue. The probability of this happening on the leader is low. If it happens on the follower, then the follower can be recreated from a leader.