[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:24.787705 20525 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.11.126:42995
I20260812 06:17:24.788734 20525 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:24.789331 20525 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.795394 20538 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.795372 20533 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.795650 20525 server_base.cc:1061] running on GCE node
W20260812 06:17:24.795663 20532 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.796314 20525 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.796435 20525 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.796484 20525 hybrid_clock.cc:648] HybridClock initialized: now 1786515444796482 us; error 0 us; skew 500 ppm
I20260812 06:17:24.798274 20525 webserver.cc:533] Webserver started at http://127.20.11.126:33983/ using document root <none> and password file <none>
I20260812 06:17:24.798817 20525 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.798909 20525 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.799165 20525 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.800882 20525 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/master-0-root/instance:
uuid: "f53acab916f14b3c84bbde9b4192a2ca"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-gmjp"
I20260812 06:17:24.804195 20525 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:24.806129 20548 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.807037 20525 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:24.807171 20525 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/master-0-root
uuid: "f53acab916f14b3c84bbde9b4192a2ca"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-gmjp"
I20260812 06:17:24.807273 20525 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.831281 20525 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.831990 20525 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:24.832250 20525 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.840308 20525 rpc_server.cc:307] RPC server started. Bound to: 127.20.11.126:42995
I20260812 06:17:24.840323 20653 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.11.126:42995 every 8 connection(s)
I20260812 06:17:24.842646 20655 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.848204 20655 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca: Bootstrap starting.
I20260812 06:17:24.850585 20655 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.851526 20655 log.cc:826] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:24.853261 20655 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca: No bootstrap required, opened a new log
I20260812 06:17:24.856002 20655 raft_consensus.cc:359] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53acab916f14b3c84bbde9b4192a2ca" member_type: VOTER }
I20260812 06:17:24.856182 20655 raft_consensus.cc:385] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.856235 20655 raft_consensus.cc:740] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f53acab916f14b3c84bbde9b4192a2ca, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.856853 20655 consensus_queue.cc:260] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53acab916f14b3c84bbde9b4192a2ca" member_type: VOTER }
I20260812 06:17:24.857015 20655 raft_consensus.cc:399] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.857110 20655 raft_consensus.cc:493] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.857268 20655 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.858048 20655 raft_consensus.cc:515] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53acab916f14b3c84bbde9b4192a2ca" member_type: VOTER }
I20260812 06:17:24.858486 20655 leader_election.cc:304] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: f53acab916f14b3c84bbde9b4192a2ca; no voters: 
I20260812 06:17:24.858865 20655 leader_election.cc:290] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.859001 20659 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.859266 20659 raft_consensus.cc:697] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 1 LEADER]: Becoming Leader. State: Replica: f53acab916f14b3c84bbde9b4192a2ca, State: Running, Role: LEADER
I20260812 06:17:24.859709 20659 consensus_queue.cc:237] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53acab916f14b3c84bbde9b4192a2ca" member_type: VOTER }
I20260812 06:17:24.859814 20655 sys_catalog.cc:565] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:24.861627 20662 sys_catalog.cc:455] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [sys.catalog]: SysCatalogTable state changed. Reason: New leader f53acab916f14b3c84bbde9b4192a2ca. Latest consensus state: current_term: 1 leader_uuid: "f53acab916f14b3c84bbde9b4192a2ca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53acab916f14b3c84bbde9b4192a2ca" member_type: VOTER } }
I20260812 06:17:24.861613 20660 sys_catalog.cc:455] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f53acab916f14b3c84bbde9b4192a2ca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f53acab916f14b3c84bbde9b4192a2ca" member_type: VOTER } }
I20260812 06:17:24.861755 20660 sys_catalog.cc:458] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.861755 20662 sys_catalog.cc:458] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.862196 20525 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:24.862200 20684 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:24.864501 20684 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:24.869107 20684 catalog_manager.cc:1383] Generated new cluster ID: c1d73fa15b0742b1ac8f71c7f68ed9fa
I20260812 06:17:24.869177 20684 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:24.885149 20684 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:24.885934 20684 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:24.894577 20684 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca: Generated new TSK 0
I20260812 06:17:24.895212 20684 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:24.927170 20525 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.930034 20693 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.930056 20697 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.930138 20699 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.930401 20525 server_base.cc:1061] running on GCE node
I20260812 06:17:24.930562 20525 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.930606 20525 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.930629 20525 hybrid_clock.cc:648] HybridClock initialized: now 1786515444930628 us; error 0 us; skew 500 ppm
I20260812 06:17:24.931542 20525 webserver.cc:533] Webserver started at http://127.20.11.65:32847/ using document root <none> and password file <none>
I20260812 06:17:24.931720 20525 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.931779 20525 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.931859 20525 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.932324 20525 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/instance:
uuid: "04c77dfa3d0f4694b9f01994e7376b74"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-gmjp"
I20260812 06:17:24.934144 20525 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:24.935211 20710 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.935521 20525 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:24.935611 20525 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root
uuid: "04c77dfa3d0f4694b9f01994e7376b74"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-gmjp"
I20260812 06:17:24.935705 20525 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.941349 20525 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.941733 20525 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.942188 20525 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:24.943066 20525 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:24.943142 20525 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.943214 20525 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:24.943269 20525 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.950217 20525 rpc_server.cc:307] RPC server started. Bound to: 127.20.11.65:36749
I20260812 06:17:24.950278 20836 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.11.65:36749 every 8 connection(s)
I20260812 06:17:24.963574 20837 heartbeater.cc:344] Connected to a master server at 127.20.11.126:42995
I20260812 06:17:24.963809 20837 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:24.964291 20837 heartbeater.cc:507] Master 127.20.11.126:42995 requested a full tablet report, sending...
I20260812 06:17:24.965736 20580 ts_manager.cc:194] Registered new tserver with Master: 04c77dfa3d0f4694b9f01994e7376b74 (127.20.11.65:36749)
I20260812 06:17:24.966413 20525 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015559253s
I20260812 06:17:24.967083 20580 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47096
I20260812 06:17:24.975409 20580 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47112:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:24.988569 20760 tablet_service.cc:1511] Processing CreateTablet for tablet e028e3dcd8e944c9acc09385b39d5dc7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=403b038fa5504a8a8e4070bf3e186265]), partition=
I20260812 06:17:24.989001 20760 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e028e3dcd8e944c9acc09385b39d5dc7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.991119 20857 tablet_bootstrap.cc:492] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Bootstrap starting.
I20260812 06:17:24.992154 20857 tablet_bootstrap.cc:654] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.993683 20857 tablet_bootstrap.cc:492] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: No bootstrap required, opened a new log
I20260812 06:17:24.993804 20857 ts_tablet_manager.cc:1403] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:24.994258 20857 raft_consensus.cc:359] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04c77dfa3d0f4694b9f01994e7376b74" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 36749 } }
I20260812 06:17:24.994379 20857 raft_consensus.cc:385] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.994426 20857 raft_consensus.cc:740] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 04c77dfa3d0f4694b9f01994e7376b74, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.994598 20857 consensus_queue.cc:260] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04c77dfa3d0f4694b9f01994e7376b74" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 36749 } }
I20260812 06:17:24.994714 20857 raft_consensus.cc:399] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.994773 20857 raft_consensus.cc:493] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.994838 20857 raft_consensus.cc:3060] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.995615 20857 raft_consensus.cc:515] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04c77dfa3d0f4694b9f01994e7376b74" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 36749 } }
I20260812 06:17:24.995779 20857 leader_election.cc:304] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 04c77dfa3d0f4694b9f01994e7376b74; no voters: 
I20260812 06:17:24.996007 20857 leader_election.cc:290] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.996100 20860 raft_consensus.cc:2804] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.996313 20860 raft_consensus.cc:697] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 1 LEADER]: Becoming Leader. State: Replica: 04c77dfa3d0f4694b9f01994e7376b74, State: Running, Role: LEADER
I20260812 06:17:24.996424 20857 ts_tablet_manager.cc:1434] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:24.996567 20860 consensus_queue.cc:237] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04c77dfa3d0f4694b9f01994e7376b74" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 36749 } }
I20260812 06:17:24.996707 20837 heartbeater.cc:499] Master 127.20.11.126:42995 was elected leader, sending a full tablet report...
I20260812 06:17:24.999300 20580 catalog_manager.cc:5719] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 reported cstate change: term changed from 0 to 1, leader changed from <none> to 04c77dfa3d0f4694b9f01994e7376b74 (127.20.11.65). New cstate: current_term: 1 leader_uuid: "04c77dfa3d0f4694b9f01994e7376b74" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "04c77dfa3d0f4694b9f01994e7376b74" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 36749 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:25.061211 20525 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.020s	sys 0.005s
I20260812 06:17:25.201342 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=19.054940
I20260812 06:17:25.384756 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.183s	user 0.148s	sys 0.032s Metrics: {"bytes_written":12635687,"cfile_init":1,"compiler_manager_pool.queue_time_us":212,"delete_count":0,"dirs.queue_time_us":115,"dirs.run_cpu_time_us":301,"dirs.run_wall_time_us":815,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45607,"lbm_writes_lt_1ms":765,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":166784,"thread_start_us":140,"threads_started":1,"update_count":1540}
I20260812 06:17:25.385856 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7): free 20743880 bytes of WAL
I20260812 06:17:25.386178 20724 log_reader.cc:385] T e028e3dcd8e944c9acc09385b39d5dc7: removed 2 log segments from log reader
I20260812 06:17:25.386252 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000001 (ops 1-6)
I20260812 06:17:25.386319 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000002 (ops 7-11)
I20260812 06:17:25.391832 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:25.392143 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7): 16411392 bytes on disk
I20260812 06:17:25.392902 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.393345 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:25.417773 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":4184707,"delete_count":0,"lbm_write_time_us":6429,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:17:25.418210 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:25.430474 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4690,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.430948 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:25.595813 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.165s	user 0.124s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":508,"lbm_read_time_us":11999,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27338,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":337,"threads_started":5,"update_count":2500}
I20260812 06:17:25.596438 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=10.126437
I20260812 06:17:25.636682 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.040s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17552,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.637142 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:25.647514 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.647931 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:25.775079 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.127s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":970,"lbm_read_time_us":9223,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24653,"lbm_writes_lt_1ms":443,"mutex_wait_us":297,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.775574 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=10.126437
I20260812 06:17:25.818392 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.043s	user 0.031s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19146,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.818928 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:25.830791 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.831225 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:25.956187 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.125s	user 0.096s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":9276,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23180,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:17:25.956821 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=10.126437
I20260812 06:17:26.000628 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.044s	user 0.030s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20583,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.001176 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.019533 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.020098 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:26.167353 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.147s	user 0.117s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":847,"lbm_read_time_us":9939,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29648,"lbm_writes_lt_1ms":443,"mutex_wait_us":291,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:17:26.167858 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=11.118625
I20260812 06:17:26.215219 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.047s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17852,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.215803 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.227452 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.227907 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.238045 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.238474 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:26.423290 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.185s	user 0.150s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":328,"lbm_read_time_us":13206,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34295,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.423856 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:26.477768 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.054s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.478814 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.497211 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.497785 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:26.658780 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.161s	user 0.131s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":734,"lbm_read_time_us":11774,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27004,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:26.659382 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=11.118625
I20260812 06:17:26.698748 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16831,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.699447 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.731920 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.032s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6052,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.732514 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.747776 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.015s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.748381 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:26.786499 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.038s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1198,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1701,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:26.787398 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7): free 132571327 bytes of WAL
I20260812 06:17:26.787683 20724 log_reader.cc:385] T e028e3dcd8e944c9acc09385b39d5dc7: removed 13 log segments from log reader
I20260812 06:17:26.787745 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000003 (ops 12-16)
I20260812 06:17:26.787786 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000004 (ops 17-21)
I20260812 06:17:26.787817 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000005 (ops 22-26)
I20260812 06:17:26.787845 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000006 (ops 27-30)
I20260812 06:17:26.787875 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000007 (ops 31-35)
I20260812 06:17:26.787910 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000008 (ops 36-40)
I20260812 06:17:26.787943 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000009 (ops 41-45)
I20260812 06:17:26.787981 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000010 (ops 46-50)
I20260812 06:17:26.788012 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000011 (ops 51-54)
I20260812 06:17:26.788043 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000012 (ops 55-59)
I20260812 06:17:26.788079 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000013 (ops 60-64)
I20260812 06:17:26.788110 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000014 (ops 65-69)
I20260812 06:17:26.788138 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000015 (ops 70-74)
I20260812 06:17:26.821687 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:26.822118 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.844086 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.022s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.844621 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:26.859097 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.859615 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:27.084209 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.224s	user 0.148s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2129,"lbm_read_time_us":15480,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36318,"lbm_writes_lt_1ms":743,"mutex_wait_us":48,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17536,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:17:27.084797 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7): 493 bytes on disk
I20260812 06:17:27.085222 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.085718 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:27.132113 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.046s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.132802 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:27.147432 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.148149 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:27.322386 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.174s	user 0.109s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":401,"lbm_read_time_us":14212,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29287,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:17:27.323186 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:27.373812 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.050s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22575,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:27.374344 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:27.391672 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.392237 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:27.568521 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.176s	user 0.129s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":13781,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29535,"lbm_writes_lt_1ms":543,"mutex_wait_us":356,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:27.568969 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:27.632949 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.064s	user 0.026s	sys 0.037s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24752,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.633466 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:27.644330 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.644850 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:27.819917 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.175s	user 0.086s	sys 0.088s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":966,"lbm_read_time_us":11723,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30986,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:27.820453 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:27.870675 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.050s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26166,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.871179 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:27.890928 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.020s	user 0.007s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.891389 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:28.074082 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.183s	user 0.114s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":12297,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30394,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:17:28.074698 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:28.127758 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.053s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23035,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.128501 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:28.157421 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.029s	user 0.012s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.158260 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:28.207335 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.049s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1297,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1634,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:28.208138 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=3.181125
I20260812 06:17:28.229847 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.021s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7020,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:28.230312 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7): free 116849526 bytes of WAL
I20260812 06:17:28.230549 20724 log_reader.cc:385] T e028e3dcd8e944c9acc09385b39d5dc7: removed 12 log segments from log reader
I20260812 06:17:28.230597 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000016 (ops 75-79)
I20260812 06:17:28.230628 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000017 (ops 80-84)
I20260812 06:17:28.230695 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000018 (ops 85-88)
I20260812 06:17:28.230737 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000019 (ops 89-93)
I20260812 06:17:28.230784 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000020 (ops 94-98)
I20260812 06:17:28.230824 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000021 (ops 99-102)
I20260812 06:17:28.230862 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000022 (ops 103-107)
I20260812 06:17:28.230901 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000023 (ops 108-112)
I20260812 06:17:28.230939 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000024 (ops 113-117)
I20260812 06:17:28.230979 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000025 (ops 118-122)
I20260812 06:17:28.231019 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000026 (ops 123-126)
I20260812 06:17:28.231060 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000027 (ops 127-131)
I20260812 06:17:28.256425 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:28.256891 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:28.273087 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.016s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.273494 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7): 447 bytes on disk
I20260812 06:17:28.273902 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.274362 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:28.284286 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.284759 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:28.615898 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.331s	user 0.218s	sys 0.112s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1129,"lbm_read_time_us":16015,"lbm_reads_lt_1ms":875,"lbm_write_time_us":71459,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":710,"threads_started":6,"update_count":4000}
I20260812 06:17:28.617110 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=18.063937
I20260812 06:17:28.731732 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.114s	user 0.072s	sys 0.039s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":52997,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:28.732606 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:28.780851 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.048s	user 0.019s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.781518 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:28.801064 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.802443 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:29.149320 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.346s	user 0.261s	sys 0.068s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1248,"lbm_read_time_us":26898,"lbm_reads_lt_1ms":773,"lbm_write_time_us":74145,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":509,"threads_started":4,"update_count":3500}
I20260812 06:17:29.150496 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=18.063937
I20260812 06:17:29.252908 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.102s	user 0.052s	sys 0.047s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":46416,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.253790 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:29.283378 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.029s	user 0.017s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.284072 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:29.563585 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.279s	user 0.204s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1452,"lbm_read_time_us":21030,"lbm_reads_lt_1ms":668,"lbm_write_time_us":60627,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:29.564607 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:29.684559 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.120s	user 0.081s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":49156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.685752 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:29.729915 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.044s	user 0.022s	sys 0.004s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":11092,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:17:29.730736 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:29.751451 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.020s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":7634,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:29.752744 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:30.064056 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.311s	user 0.226s	sys 0.085s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":250,"lbm_read_time_us":24104,"lbm_reads_lt_1ms":673,"lbm_write_time_us":68945,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":3000}
I20260812 06:17:30.065277 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:30.163168 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.098s	user 0.066s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":39487,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.163990 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=3.181125
I20260812 06:17:30.188041 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.024s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8029,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:30.188843 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:30.206357 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6588,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.207150 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:30.547722 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.340s	user 0.258s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":848,"lbm_read_time_us":20253,"lbm_reads_lt_1ms":673,"lbm_write_time_us":77266,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":107,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3000}
I20260812 06:17:30.549919 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=14.095187
I20260812 06:17:30.708729 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.158s	user 0.096s	sys 0.057s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":69993,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.709318 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:30.749998 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.040s	user 0.014s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.750771 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:30.771394 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.020s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.772667 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:30.826329 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushMRSOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.053s	user 0.043s	sys 0.005s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":334,"dirs.run_wall_time_us":1362,"drs_written":1,"lbm_read_time_us":115,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:17:30.827661 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7): free 128867672 bytes of WAL
I20260812 06:17:30.828049 20724 log_reader.cc:385] T e028e3dcd8e944c9acc09385b39d5dc7: removed 13 log segments from log reader
I20260812 06:17:30.828181 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000028 (ops 132-136)
I20260812 06:17:30.828253 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000029 (ops 137-141)
I20260812 06:17:30.828332 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000030 (ops 142-146)
I20260812 06:17:30.828375 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000031 (ops 147-151)
I20260812 06:17:30.828438 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000032 (ops 152-156)
I20260812 06:17:30.828502 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000033 (ops 157-160)
I20260812 06:17:30.828583 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000034 (ops 161-165)
I20260812 06:17:30.828636 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000035 (ops 166-170)
I20260812 06:17:30.828686 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000036 (ops 171-174)
I20260812 06:17:30.828720 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000037 (ops 175-179)
I20260812 06:17:30.828771 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000038 (ops 180-184)
I20260812 06:17:30.828809 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000039 (ops 185-188)
I20260812 06:17:30.828857 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000040 (ops 189-193)
I20260812 06:17:30.877645 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.050s	user 0.001s	sys 0.047s Metrics: {}
I20260812 06:17:30.878525 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7): 508 bytes on disk
I20260812 06:17:30.879705 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: UndoDeltaBlockGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":239,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.880760 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:30.923051 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.042s	user 0.017s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":12232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.923780 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7): free 12018006 bytes of WAL
I20260812 06:17:30.924083 20724 log_reader.cc:385] T e028e3dcd8e944c9acc09385b39d5dc7: removed 1 log segments from log reader
I20260812 06:17:30.924217 20724 log.cc:1079] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/e028e3dcd8e944c9acc09385b39d5dc7/wal-000000041 (ops 194-198)
I20260812 06:17:30.927973 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: LogGCOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:30.928638 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=2.188937
I20260812 06:17:30.950182 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: FlushDeltaMemStoresOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.021s	user 0.016s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.951068 20840 maintenance_manager.cc:419] P 04c77dfa3d0f4694b9f01994e7376b74: Scheduling MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7): perf score=1.000000
I20260812 06:17:30.995558 20525 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.934s	user 2.115s	sys 0.152s
I20260812 06:17:31.161268 20525 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.164s	user 0.005s	sys 0.000s
I20260812 06:17:31.162302 20525 tablet_server.cc:179] TabletServer@127.20.11.65:0 shutting down...
I20260812 06:17:31.276002 20724 maintenance_manager.cc:643] P 04c77dfa3d0f4694b9f01994e7376b74: MajorDeltaCompactionOp(e028e3dcd8e944c9acc09385b39d5dc7) complete. Timing: real 0.325s	user 0.239s	sys 0.084s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082283,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1160,"lbm_read_time_us":29188,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":870,"lbm_write_time_us":71883,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":610,"threads_started":6,"update_count":4000}
I20260812 06:17:31.278475 20525 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:31.279055 20525 tablet_replica.cc:333] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74: stopping tablet replica
I20260812 06:17:31.279568 20525 raft_consensus.cc:2243] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:31.279973 20525 raft_consensus.cc:2272] T e028e3dcd8e944c9acc09385b39d5dc7 P 04c77dfa3d0f4694b9f01994e7376b74 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:31.298463 20525 tablet_server.cc:196] TabletServer@127.20.11.65:0 shutdown complete.
I20260812 06:17:31.352902 20525 master.cc:562] Master@127.20.11.126:42995 shutting down...
I20260812 06:17:31.358868 20525 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:31.359174 20525 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:31.359333 20525 tablet_replica.cc:333] T 00000000000000000000000000000000 P f53acab916f14b3c84bbde9b4192a2ca: stopping tablet replica
I20260812 06:17:31.373237 20525 master.cc:584] Master@127.20.11.126:42995 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6717 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:31.508872 20525 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.11.126:37637
I20260812 06:17:31.512339 20525 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:31.516191 20924 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:31.516264 20923 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:31.516083 20926 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:31.517324 20525 server_base.cc:1061] running on GCE node
I20260812 06:17:31.517508 20525 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:31.517551 20525 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:31.517643 20525 hybrid_clock.cc:648] HybridClock initialized: now 1786515451517642 us; error 0 us; skew 500 ppm
I20260812 06:17:31.519387 20525 webserver.cc:533] Webserver started at http://127.20.11.126:35009/ using document root <none> and password file <none>
I20260812 06:17:31.519718 20525 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:31.519804 20525 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:31.519907 20525 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:31.520701 20525 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/master-0-root/instance:
uuid: "d82aa1e17cb04d4ab075a851b7929f31"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-gmjp"
I20260812 06:17:31.523392 20525 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:31.525143 20938 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.525573 20525 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:31.525748 20525 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/master-0-root
uuid: "d82aa1e17cb04d4ab075a851b7929f31"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-gmjp"
I20260812 06:17:31.525880 20525 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:31.548673 20525 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:31.549363 20525 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:31.557374 20525 rpc_server.cc:307] RPC server started. Bound to: 127.20.11.126:37637
I20260812 06:17:31.561604 21028 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.11.126:37637 every 8 connection(s)
I20260812 06:17:31.565344 21029 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:31.587914 21029 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31: Bootstrap starting.
I20260812 06:17:31.589336 21029 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:31.591324 21029 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31: No bootstrap required, opened a new log
I20260812 06:17:31.592090 21029 raft_consensus.cc:359] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d82aa1e17cb04d4ab075a851b7929f31" member_type: VOTER }
I20260812 06:17:31.592296 21029 raft_consensus.cc:385] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:31.592401 21029 raft_consensus.cc:740] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d82aa1e17cb04d4ab075a851b7929f31, State: Initialized, Role: FOLLOWER
I20260812 06:17:31.592684 21029 consensus_queue.cc:260] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d82aa1e17cb04d4ab075a851b7929f31" member_type: VOTER }
I20260812 06:17:31.592845 21029 raft_consensus.cc:399] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:31.592984 21029 raft_consensus.cc:493] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:31.593122 21029 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:31.594458 21029 raft_consensus.cc:515] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d82aa1e17cb04d4ab075a851b7929f31" member_type: VOTER }
I20260812 06:17:31.594715 21029 leader_election.cc:304] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: d82aa1e17cb04d4ab075a851b7929f31; no voters: 
I20260812 06:17:31.595034 21029 leader_election.cc:290] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:31.595292 21039 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:31.595636 21039 raft_consensus.cc:697] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 1 LEADER]: Becoming Leader. State: Replica: d82aa1e17cb04d4ab075a851b7929f31, State: Running, Role: LEADER
I20260812 06:17:31.595904 21029 sys_catalog.cc:565] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:31.595944 21039 consensus_queue.cc:237] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d82aa1e17cb04d4ab075a851b7929f31" member_type: VOTER }
I20260812 06:17:31.597355 21040 sys_catalog.cc:455] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d82aa1e17cb04d4ab075a851b7929f31" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d82aa1e17cb04d4ab075a851b7929f31" member_type: VOTER } }
I20260812 06:17:31.597553 21040 sys_catalog.cc:458] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:31.597370 21043 sys_catalog.cc:455] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d82aa1e17cb04d4ab075a851b7929f31. Latest consensus state: current_term: 1 leader_uuid: "d82aa1e17cb04d4ab075a851b7929f31" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d82aa1e17cb04d4ab075a851b7929f31" member_type: VOTER } }
I20260812 06:17:31.597803 21043 sys_catalog.cc:458] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:31.598449 21058 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:31.599611 21058 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:31.599924 20525 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:31.602797 21058 catalog_manager.cc:1383] Generated new cluster ID: 59a5e635ed454af9af064b9ec4fabcc2
I20260812 06:17:31.602870 21058 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:31.630280 21058 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:31.631263 21058 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:31.643476 21058 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31: Generated new TSK 0
I20260812 06:17:31.643754 21058 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:31.665126 20525 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:31.668368 21082 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:31.668334 21084 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:31.669024 20525 server_base.cc:1061] running on GCE node
W20260812 06:17:31.669090 21087 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:31.669605 20525 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:31.669684 20525 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:31.669773 20525 hybrid_clock.cc:648] HybridClock initialized: now 1786515451669772 us; error 0 us; skew 500 ppm
I20260812 06:17:31.671460 20525 webserver.cc:533] Webserver started at http://127.20.11.65:39417/ using document root <none> and password file <none>
I20260812 06:17:31.671754 20525 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:31.671880 20525 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:31.672139 20525 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:31.672976 20525 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/instance:
uuid: "1228fc2b06ea422e948d1b180eb7e48f"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-gmjp"
I20260812 06:17:31.675875 20525 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.003s
I20260812 06:17:31.677768 21097 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.678260 20525 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:31.678397 20525 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root
uuid: "1228fc2b06ea422e948d1b180eb7e48f"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-gmjp"
I20260812 06:17:31.678561 20525 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:31.692662 20525 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:31.693305 20525 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:31.693830 20525 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:31.694658 20525 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:31.694792 20525 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.694952 20525 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:31.695031 20525 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.704083 20525 rpc_server.cc:307] RPC server started. Bound to: 127.20.11.65:35909
I20260812 06:17:31.704133 21208 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.11.65:35909 every 8 connection(s)
I20260812 06:17:31.718756 21212 heartbeater.cc:344] Connected to a master server at 127.20.11.126:37637
I20260812 06:17:31.718918 21212 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:31.719254 21212 heartbeater.cc:507] Master 127.20.11.126:37637 requested a full tablet report, sending...
I20260812 06:17:31.720664 20971 ts_manager.cc:194] Registered new tserver with Master: 1228fc2b06ea422e948d1b180eb7e48f (127.20.11.65:35909)
I20260812 06:17:31.721662 20525 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016776048s
I20260812 06:17:31.721879 20971 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37082
I20260812 06:17:31.733160 20971 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37084:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:31.748838 21145 tablet_service.cc:1511] Processing CreateTablet for tablet c21ecb7d17d242a9921c2ac69427c73f (DEFAULT_TABLE table=heavy-update-compaction-test [id=ae3f79fe7230496fa64e9c9bf45f7cd4]), partition=
I20260812 06:17:31.749287 21145 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c21ecb7d17d242a9921c2ac69427c73f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:31.752948 21236 tablet_bootstrap.cc:492] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Bootstrap starting.
I20260812 06:17:31.754528 21236 tablet_bootstrap.cc:654] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:31.756608 21236 tablet_bootstrap.cc:492] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: No bootstrap required, opened a new log
I20260812 06:17:31.756841 21236 ts_tablet_manager.cc:1403] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:31.757643 21236 raft_consensus.cc:359] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1228fc2b06ea422e948d1b180eb7e48f" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 35909 } }
I20260812 06:17:31.757798 21236 raft_consensus.cc:385] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:31.757899 21236 raft_consensus.cc:740] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1228fc2b06ea422e948d1b180eb7e48f, State: Initialized, Role: FOLLOWER
I20260812 06:17:31.758183 21236 consensus_queue.cc:260] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1228fc2b06ea422e948d1b180eb7e48f" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 35909 } }
I20260812 06:17:31.758307 21236 raft_consensus.cc:399] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:31.758417 21236 raft_consensus.cc:493] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:31.758587 21236 raft_consensus.cc:3060] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:31.759960 21236 raft_consensus.cc:515] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1228fc2b06ea422e948d1b180eb7e48f" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 35909 } }
I20260812 06:17:31.760278 21236 leader_election.cc:304] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 1228fc2b06ea422e948d1b180eb7e48f; no voters: 
I20260812 06:17:31.760690 21236 leader_election.cc:290] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:31.761013 21239 raft_consensus.cc:2804] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:31.761418 21212 heartbeater.cc:499] Master 127.20.11.126:37637 was elected leader, sending a full tablet report...
I20260812 06:17:31.761495 21239 raft_consensus.cc:697] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 1 LEADER]: Becoming Leader. State: Replica: 1228fc2b06ea422e948d1b180eb7e48f, State: Running, Role: LEADER
I20260812 06:17:31.761816 21239 consensus_queue.cc:237] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1228fc2b06ea422e948d1b180eb7e48f" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 35909 } }
I20260812 06:17:31.761977 21236 ts_tablet_manager.cc:1434] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Time spent starting tablet: real 0.005s	user 0.005s	sys 0.000s
I20260812 06:17:31.764743 20971 catalog_manager.cc:5719] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f reported cstate change: term changed from 0 to 1, leader changed from <none> to 1228fc2b06ea422e948d1b180eb7e48f (127.20.11.65). New cstate: current_term: 1 leader_uuid: "1228fc2b06ea422e948d1b180eb7e48f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1228fc2b06ea422e948d1b180eb7e48f" member_type: VOTER last_known_addr { host: "127.20.11.65" port: 35909 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:31.875101 20525 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.097s	user 0.036s	sys 0.008s
I20260812 06:17:31.955719 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=6.156503
I20260812 06:17:32.159227 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.203s	user 0.145s	sys 0.039s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":782,"drs_written":1,"lbm_read_time_us":186,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46361,"lbm_writes_lt_1ms":357,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"update_count":1000}
I20260812 06:17:32.160307 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling LogGCOp(c21ecb7d17d242a9921c2ac69427c73f): free 11976772 bytes of WAL
I20260812 06:17:32.160640 21106 log_reader.cc:385] T c21ecb7d17d242a9921c2ac69427c73f: removed 1 log segments from log reader
I20260812 06:17:32.160709 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000001 (ops 1-6)
I20260812 06:17:32.165020 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: LogGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:32.165633 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:32.190304 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.024s	user 0.010s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":9369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.191147 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:32.407061 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.216s	user 0.133s	sys 0.077s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446969,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":67,"lbm_read_time_us":17323,"lbm_reads_lt_1ms":368,"lbm_write_time_us":43700,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":232,"threads_started":5,"update_count":1500}
I20260812 06:17:32.407604 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:32.455291 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.047s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19499,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.455791 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:32.466064 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.466852 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:32.604269 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.137s	user 0.104s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549381,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1323,"lbm_read_time_us":9724,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22969,"lbm_writes_lt_1ms":443,"mutex_wait_us":379,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27008,"update_count":2000}
I20260812 06:17:32.604862 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:32.654474 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.049s	user 0.029s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18003,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.654963 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:32.666016 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.666572 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f): 4103815 bytes on disk
I20260812 06:17:32.667238 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.667737 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:32.794873 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.127s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":291,"lbm_read_time_us":9292,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22707,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2000}
I20260812 06:17:32.795430 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:32.841096 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.045s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16839,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.841634 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:32.852098 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.852674 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:32.970822 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.118s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549380,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":542,"lbm_read_time_us":9508,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20684,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:17:32.971370 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:33.017531 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.046s	user 0.018s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15851,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.018173 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:33.029008 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.029552 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:33.187497 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.158s	user 0.099s	sys 0.058s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":316,"lbm_read_time_us":11254,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25740,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:17:33.188410 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:33.233208 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.045s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16550,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.233649 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:33.243865 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.244588 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:33.375926 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.131s	user 0.110s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549381,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":72,"lbm_read_time_us":7534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26843,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:17:33.376755 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:33.408372 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.031s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14104,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.408793 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:33.419122 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.419731 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:33.542405 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.122s	user 0.096s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":9804,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22284,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:17:33.543165 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=10.126437
I20260812 06:17:33.591913 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.049s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20685,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.592443 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:33.603609 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.604080 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:33.633632 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1292,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1663,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:33.634305 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling LogGCOp(c21ecb7d17d242a9921c2ac69427c73f): free 120553382 bytes of WAL
I20260812 06:17:33.634558 21106 log_reader.cc:385] T c21ecb7d17d242a9921c2ac69427c73f: removed 12 log segments from log reader
I20260812 06:17:33.634625 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000002 (ops 7-11)
I20260812 06:17:33.634680 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000003 (ops 12-16)
I20260812 06:17:33.634737 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000004 (ops 17-21)
I20260812 06:17:33.634778 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000005 (ops 22-26)
I20260812 06:17:33.634812 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000006 (ops 27-30)
I20260812 06:17:33.634845 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000007 (ops 31-35)
I20260812 06:17:33.634888 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000008 (ops 36-40)
I20260812 06:17:33.634927 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000009 (ops 41-45)
I20260812 06:17:33.634963 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000010 (ops 46-50)
I20260812 06:17:33.634999 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000011 (ops 51-55)
I20260812 06:17:33.635035 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000012 (ops 56-60)
I20260812 06:17:33.635072 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000013 (ops 61-64)
I20260812 06:17:33.660777 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: LogGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:33.661243 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f): 482 bytes on disk
I20260812 06:17:33.661896 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.662503 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=3.181125
I20260812 06:17:33.675648 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5210313,"delete_count":0,"lbm_write_time_us":5248,"lbm_writes_lt_1ms":130,"reinsert_count":0,"update_count":635}
I20260812 06:17:33.676067 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.196750
I20260812 06:17:33.685752 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":2911,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:17:33.686311 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:33.860404 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.174s	user 0.121s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28754419,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":312,"lbm_read_time_us":13108,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34244,"lbm_writes_lt_1ms":643,"mutex_wait_us":1125,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23424,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:17:33.860940 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:33.909998 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21825,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.910485 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:33.920599 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.920993 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:34.083257 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.162s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651792,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":720,"lbm_read_time_us":10444,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28935,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:17:34.083961 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:34.132898 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.049s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21611,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.133339 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:34.287304 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.154s	user 0.075s	sys 0.074s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20549264,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":152,"lbm_read_time_us":10709,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25040,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:17:34.288125 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=11.118625
I20260812 06:17:34.330837 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.042s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717747,"delete_count":0,"lbm_write_time_us":17201,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:34.331274 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:34.342492 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.342938 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:34.352216 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3507,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.352615 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:34.533563 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.181s	user 0.121s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651916,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":613,"lbm_read_time_us":12899,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28905,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:34.534122 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:34.603308 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.069s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":45043,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.603878 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:34.615808 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.616355 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:34.774552 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.158s	user 0.122s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":117,"lbm_read_time_us":10050,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29316,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:17:34.775231 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:34.833598 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.058s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23893,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.834167 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:34.845327 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.845770 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:34.996186 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.150s	user 0.105s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1082,"lbm_read_time_us":11747,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31730,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:17:34.996758 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=11.118625
I20260812 06:17:35.036835 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.040s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18093,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:17:35.037364 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:35.048571 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.049012 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:35.081331 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1334,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1898,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:35.082005 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling LogGCOp(c21ecb7d17d242a9921c2ac69427c73f): free 124710308 bytes of WAL
I20260812 06:17:35.082265 21106 log_reader.cc:385] T c21ecb7d17d242a9921c2ac69427c73f: removed 12 log segments from log reader
I20260812 06:17:35.082337 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000014 (ops 65-69)
I20260812 06:17:35.082389 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000015 (ops 70-74)
I20260812 06:17:35.082448 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000016 (ops 75-79)
I20260812 06:17:35.082502 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000017 (ops 80-84)
I20260812 06:17:35.082544 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000018 (ops 85-89)
I20260812 06:17:35.082581 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000019 (ops 90-94)
I20260812 06:17:35.082620 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000020 (ops 95-99)
I20260812 06:17:35.082659 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000021 (ops 100-104)
I20260812 06:17:35.082698 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000022 (ops 105-109)
I20260812 06:17:35.082738 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000023 (ops 110-114)
I20260812 06:17:35.082777 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000024 (ops 115-119)
I20260812 06:17:35.082815 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000025 (ops 120-124)
I20260812 06:17:35.109390 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: LogGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:35.109961 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f): 476 bytes on disk
I20260812 06:17:35.110531 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.111119 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=6.157687
I20260812 06:17:35.134431 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.023s	user 0.013s	sys 0.008s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10044,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:35.135030 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:35.305573 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.170s	user 0.109s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754316,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":557,"lbm_read_time_us":11648,"lbm_reads_lt_1ms":669,"lbm_write_time_us":35664,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:35.306732 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:35.351994 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.045s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.352900 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:35.368752 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.016s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.369241 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:35.521302 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.152s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651792,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":907,"lbm_read_time_us":9137,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29623,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33024,"update_count":2500}
I20260812 06:17:35.521917 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:35.571578 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.049s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19604,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.572044 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:35.583681 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.584237 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:35.734704 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.150s	user 0.102s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":11257,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29770,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:17:35.735281 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=11.118625
I20260812 06:17:35.771210 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15201,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:35.771849 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:35.790120 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5447,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.790807 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:35.912783 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.122s	user 0.093s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549373,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":7582,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23763,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:17:35.913540 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=11.118625
I20260812 06:17:35.959774 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.046s	user 0.012s	sys 0.030s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17350,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:35.960520 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:35.973302 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4797,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.973867 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:36.114998 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.141s	user 0.116s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549372,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":8338,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23633,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.115603 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:36.164749 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.049s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24006,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.165400 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:36.178828 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.179376 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:36.353287 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.174s	user 0.127s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":10897,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26927,"lbm_writes_lt_1ms":543,"mutex_wait_us":214,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60928,"update_count":2500}
I20260812 06:17:36.353808 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=14.095187
I20260812 06:17:36.412221 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.058s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26026,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.412716 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:36.423291 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.424089 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:36.455497 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushMRSOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1396,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1862,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:36.456147 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling LogGCOp(c21ecb7d17d242a9921c2ac69427c73f): free 124710544 bytes of WAL
I20260812 06:17:36.456437 21106 log_reader.cc:385] T c21ecb7d17d242a9921c2ac69427c73f: removed 12 log segments from log reader
I20260812 06:17:36.456480 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000026 (ops 125-129)
I20260812 06:17:36.456507 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000027 (ops 130-134)
I20260812 06:17:36.456549 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000028 (ops 135-139)
I20260812 06:17:36.456591 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000029 (ops 140-144)
I20260812 06:17:36.456641 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000030 (ops 145-149)
I20260812 06:17:36.456681 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000031 (ops 150-154)
I20260812 06:17:36.456723 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000032 (ops 155-159)
I20260812 06:17:36.456760 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000033 (ops 160-164)
I20260812 06:17:36.456799 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000034 (ops 165-169)
I20260812 06:17:36.456845 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000035 (ops 170-174)
I20260812 06:17:36.456889 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000036 (ops 175-179)
I20260812 06:17:36.456930 21106 log.cc:1079] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: Deleting log segment in path: /tmp/dist-test-task6b6nDd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444777360-20525-0/minicluster-data/ts-0-root/wals/c21ecb7d17d242a9921c2ac69427c73f/wal-000000037 (ops 180-184)
I20260812 06:17:36.484952 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: LogGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:36.485536 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f): 472 bytes on disk
I20260812 06:17:36.486073 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: UndoDeltaBlockGCOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.486634 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=3.181125
I20260812 06:17:36.505990 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:36.506465 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:36.516398 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.516924 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:36.756541 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.239s	user 0.139s	sys 0.093s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856847,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":7613,"lbm_read_time_us":16632,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38026,"lbm_writes_lt_1ms":743,"mutex_wait_us":2410,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:17:36.757325 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=17.071750
I20260812 06:17:36.808588 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.051s	user 0.018s	sys 0.032s Metrics: {"bytes_written":19609788,"delete_count":0,"lbm_write_time_us":23092,"lbm_writes_lt_1ms":481,"mutex_wait_us":842,"reinsert_count":0,"update_count":2390}
I20260812 06:17:36.809053 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:36.823529 20525 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.948s	user 1.871s	sys 0.094s
I20260812 06:17:36.824896 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.016s	user 0.004s	sys 0.001s Metrics: {"bytes_written":1312957,"delete_count":0,"lbm_write_time_us":1427,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:17:36.825327 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=2.188937
I20260812 06:17:36.834348 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: FlushDeltaMemStoresOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:17:36.834764 21214 maintenance_manager.cc:419] P 1228fc2b06ea422e948d1b180eb7e48f: Scheduling MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f): perf score=1.000000
I20260812 06:17:36.894480 20525 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.002s	sys 0.000s
I20260812 06:17:36.895119 20525 tablet_server.cc:179] TabletServer@127.20.11.65:0 shutting down...
I20260812 06:17:36.984086 21106 maintenance_manager.cc:643] P 1228fc2b06ea422e948d1b180eb7e48f: MajorDeltaCompactionOp(c21ecb7d17d242a9921c2ac69427c73f) complete. Timing: real 0.149s	user 0.115s	sys 0.033s Metrics: {"cfile_cache_hit":196,"cfile_cache_hit_bytes":7963008,"cfile_cache_miss":437,"cfile_cache_miss_bytes":20791248,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":951,"lbm_read_time_us":8479,"lbm_reads_lt_1ms":469,"lbm_write_time_us":30301,"lbm_writes_lt_1ms":643,"mutex_wait_us":84,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":3000}
I20260812 06:17:36.984702 20525 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:36.984952 20525 tablet_replica.cc:333] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f: stopping tablet replica
I20260812 06:17:36.985131 20525 raft_consensus.cc:2243] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:36.985304 20525 raft_consensus.cc:2272] T c21ecb7d17d242a9921c2ac69427c73f P 1228fc2b06ea422e948d1b180eb7e48f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:36.999234 20525 tablet_server.cc:196] TabletServer@127.20.11.65:0 shutdown complete.
I20260812 06:17:37.037474 20525 master.cc:562] Master@127.20.11.126:37637 shutting down...
I20260812 06:17:37.041024 20525 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.041227 20525 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.041318 20525 tablet_replica.cc:333] T 00000000000000000000000000000000 P d82aa1e17cb04d4ab075a851b7929f31: stopping tablet replica
I20260812 06:17:37.053623 20525 master.cc:584] Master@127.20.11.126:37637 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5639 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12358 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test suite ran. (12358 ms total)
[  PASSED  ] 2 tests.
