[==========] 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:16:55.582543 19549 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.23.126:44907
I20260812 06:16:55.583459 19549 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:16:55.584020 19549 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:55.590098 19549 server_base.cc:1061] running on GCE node
W20260812 06:16:55.589944 19556 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:16:55.589977 19558 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:16:55.590224 19562 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:16:55.590890 19549 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:55.591017 19549 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:16:55.591058 19549 hybrid_clock.cc:648] HybridClock initialized: now 1786515415591055 us; error 0 us; skew 500 ppm
I20260812 06:16:55.592661 19549 webserver.cc:533] Webserver started at http://127.19.23.126:43827/ using document root <none> and password file <none>
I20260812 06:16:55.593125 19549 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:55.593185 19549 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:55.593394 19549 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:55.594895 19549 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/master-0-root/instance:
uuid: "65816a8c861149db9ab056d5e4db27bd"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-1vmg"
I20260812 06:16:55.597997 19549 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:55.599893 19571 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:16:55.600775 19549 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:55.600874 19549 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/master-0-root
uuid: "65816a8c861149db9ab056d5e4db27bd"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-1vmg"
I20260812 06:16:55.600950 19549 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-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:16:55.611027 19549 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:55.611536 19549 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:16:55.611685 19549 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:55.618469 19549 rpc_server.cc:307] RPC server started. Bound to: 127.19.23.126:44907
I20260812 06:16:55.618469 19662 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.23.126:44907 every 8 connection(s)
I20260812 06:16:55.620529 19666 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:16:55.625504 19666 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: Bootstrap starting.
I20260812 06:16:55.627720 19666 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:55.628541 19666 log.cc:826] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:55.629957 19666 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: No bootstrap required, opened a new log
I20260812 06:16:55.632483 19666 raft_consensus.cc:359] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65816a8c861149db9ab056d5e4db27bd" member_type: VOTER }
I20260812 06:16:55.632627 19666 raft_consensus.cc:385] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:55.632669 19666 raft_consensus.cc:740] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 65816a8c861149db9ab056d5e4db27bd, State: Initialized, Role: FOLLOWER
I20260812 06:16:55.633131 19666 consensus_queue.cc:260] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [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: "65816a8c861149db9ab056d5e4db27bd" member_type: VOTER }
I20260812 06:16:55.633249 19666 raft_consensus.cc:399] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:55.633291 19666 raft_consensus.cc:493] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:55.633371 19666 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:55.655365 19666 raft_consensus.cc:515] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65816a8c861149db9ab056d5e4db27bd" member_type: VOTER }
I20260812 06:16:55.655810 19666 leader_election.cc:304] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [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: 65816a8c861149db9ab056d5e4db27bd; no voters: 
I20260812 06:16:55.656104 19666 leader_election.cc:290] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:55.656232 19674 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:55.656448 19674 raft_consensus.cc:697] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 1 LEADER]: Becoming Leader. State: Replica: 65816a8c861149db9ab056d5e4db27bd, State: Running, Role: LEADER
I20260812 06:16:55.656880 19674 consensus_queue.cc:237] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [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: "65816a8c861149db9ab056d5e4db27bd" member_type: VOTER }
I20260812 06:16:55.657042 19666 sys_catalog.cc:565] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:55.658658 19682 sys_catalog.cc:455] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 65816a8c861149db9ab056d5e4db27bd. Latest consensus state: current_term: 1 leader_uuid: "65816a8c861149db9ab056d5e4db27bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65816a8c861149db9ab056d5e4db27bd" member_type: VOTER } }
I20260812 06:16:55.658764 19682 sys_catalog.cc:458] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:55.659052 19676 sys_catalog.cc:455] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "65816a8c861149db9ab056d5e4db27bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65816a8c861149db9ab056d5e4db27bd" member_type: VOTER } }
I20260812 06:16:55.659112 19676 sys_catalog.cc:458] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:55.659199 19549 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:55.661307 19709 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:55.661368 19709 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:55.661442 19706 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:55.662137 19706 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:55.666471 19706 catalog_manager.cc:1383] Generated new cluster ID: 2decb073606847878d5948fe5009f790
I20260812 06:16:55.666528 19706 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:55.675967 19706 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:55.676945 19706 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:55.696462 19706 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: Generated new TSK 0
I20260812 06:16:55.697089 19706 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:55.723791 19549 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:55.726281 19721 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:16:55.726289 19726 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:16:55.726414 19549 server_base.cc:1061] running on GCE node
W20260812 06:16:55.726285 19724 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:16:55.726687 19549 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:55.726753 19549 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:16:55.726775 19549 hybrid_clock.cc:648] HybridClock initialized: now 1786515415726775 us; error 0 us; skew 500 ppm
I20260812 06:16:55.727651 19549 webserver.cc:533] Webserver started at http://127.19.23.65:36155/ using document root <none> and password file <none>
I20260812 06:16:55.727806 19549 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:55.727860 19549 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:55.727933 19549 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:55.728348 19549 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/instance:
uuid: "8af08c3947e3485a9d92941dda33904f"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-1vmg"
I20260812 06:16:55.730089 19549 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:55.731099 19736 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:16:55.731346 19549 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:55.731415 19549 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root
uuid: "8af08c3947e3485a9d92941dda33904f"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-1vmg"
I20260812 06:16:55.731479 19549 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-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:16:55.759099 19549 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:55.759495 19549 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:55.759995 19549 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:55.760951 19549 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:55.761013 19549 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:55.761059 19549 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:55.761121 19549 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:55.766557 19549 rpc_server.cc:307] RPC server started. Bound to: 127.19.23.65:35865
I20260812 06:16:55.766615 19845 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.23.65:35865 every 8 connection(s)
I20260812 06:16:55.775135 19846 heartbeater.cc:344] Connected to a master server at 127.19.23.126:44907
I20260812 06:16:55.775327 19846 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:55.775695 19846 heartbeater.cc:507] Master 127.19.23.126:44907 requested a full tablet report, sending...
I20260812 06:16:55.776952 19606 ts_manager.cc:194] Registered new tserver with Master: 8af08c3947e3485a9d92941dda33904f (127.19.23.65:35865)
I20260812 06:16:55.777226 19549 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010084639s
I20260812 06:16:55.778044 19606 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49110
I20260812 06:16:55.786058 19606 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49124:
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:16:55.798810 19780 tablet_service.cc:1511] Processing CreateTablet for tablet 7c1c959d1f5a438a8e7dc2252a417643 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5912f753b82d45a6b07947e623e3bbe4]), partition=
I20260812 06:16:55.799304 19780 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7c1c959d1f5a438a8e7dc2252a417643. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:55.802014 19868 tablet_bootstrap.cc:492] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Bootstrap starting.
I20260812 06:16:55.803006 19868 tablet_bootstrap.cc:654] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:55.804427 19868 tablet_bootstrap.cc:492] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: No bootstrap required, opened a new log
I20260812 06:16:55.804508 19868 ts_tablet_manager.cc:1403] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:55.804992 19868 raft_consensus.cc:359] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8af08c3947e3485a9d92941dda33904f" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 35865 } }
I20260812 06:16:55.805084 19868 raft_consensus.cc:385] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:55.805106 19868 raft_consensus.cc:740] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8af08c3947e3485a9d92941dda33904f, State: Initialized, Role: FOLLOWER
I20260812 06:16:55.805220 19868 consensus_queue.cc:260] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [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: "8af08c3947e3485a9d92941dda33904f" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 35865 } }
I20260812 06:16:55.805302 19868 raft_consensus.cc:399] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:55.805347 19868 raft_consensus.cc:493] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:55.805389 19868 raft_consensus.cc:3060] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:55.857177 19868 raft_consensus.cc:515] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8af08c3947e3485a9d92941dda33904f" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 35865 } }
I20260812 06:16:55.857367 19868 leader_election.cc:304] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [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: 8af08c3947e3485a9d92941dda33904f; no voters: 
I20260812 06:16:55.857577 19868 leader_election.cc:290] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:55.857740 19870 raft_consensus.cc:2804] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:55.857962 19870 raft_consensus.cc:697] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 1 LEADER]: Becoming Leader. State: Replica: 8af08c3947e3485a9d92941dda33904f, State: Running, Role: LEADER
I20260812 06:16:55.857983 19868 ts_tablet_manager.cc:1434] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Time spent starting tablet: real 0.053s	user 0.000s	sys 0.002s
I20260812 06:16:55.858292 19846 heartbeater.cc:499] Master 127.19.23.126:44907 was elected leader, sending a full tablet report...
I20260812 06:16:55.858178 19870 consensus_queue.cc:237] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [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: "8af08c3947e3485a9d92941dda33904f" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 35865 } }
I20260812 06:16:55.861045 19606 catalog_manager.cc:5719] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f reported cstate change: term changed from 0 to 1, leader changed from <none> to 8af08c3947e3485a9d92941dda33904f (127.19.23.65). New cstate: current_term: 1 leader_uuid: "8af08c3947e3485a9d92941dda33904f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8af08c3947e3485a9d92941dda33904f" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 35865 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:55.920418 19549 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.013s	sys 0.011s
I20260812 06:16:56.017608 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushMRSOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=15.086190
I20260812 06:16:56.270984 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushMRSOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.253s	user 0.127s	sys 0.031s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":118518,"compiler_manager_pool.run_cpu_time_us":226821,"compiler_manager_pool.run_wall_time_us":227082,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":145558,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42556,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":126,"threads_started":1,"update_count":1500}
I20260812 06:16:56.272338 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling LogGCOp(7c1c959d1f5a438a8e7dc2252a417643): free 8725963 bytes of WAL
I20260812 06:16:56.272728 19744 log_reader.cc:385] T 7c1c959d1f5a438a8e7dc2252a417643: removed 1 log segments from log reader
I20260812 06:16:56.272802 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000001 (ops 1-6)
I20260812 06:16:56.275128 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: LogGCOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:56.275422 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=11.118625
I20260812 06:16:56.371555 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.096s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13540,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:56.372114 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=6.157687
I20260812 06:16:56.467208 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.095s	user 0.016s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8187,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:56.467720 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=10.126437
I20260812 06:16:56.571055 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.103s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13658,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":1500}
I20260812 06:16:56.571569 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=7.149875
I20260812 06:16:56.673257 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.102s	user 0.014s	sys 0.005s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":8056,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:56.673834 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=10.126437
I20260812 06:16:56.770681 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.097s	user 0.026s	sys 0.001s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":11744,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:56.771162 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling UndoDeltaBlockGCOp(7c1c959d1f5a438a8e7dc2252a417643): 12308958 bytes on disk
I20260812 06:16:56.771689 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: UndoDeltaBlockGCOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:56.772075 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=7.149875
I20260812 06:16:56.870630 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.098s	user 0.001s	sys 0.016s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":7465,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:56.871081 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=10.126437
I20260812 06:16:56.973860 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.103s	user 0.018s	sys 0.009s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":12140,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:56.974375 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=7.149875
I20260812 06:16:57.073933 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.099s	user 0.011s	sys 0.007s Metrics: {"bytes_written":8820443,"delete_count":0,"lbm_write_time_us":7998,"lbm_writes_lt_1ms":218,"reinsert_count":0,"update_count":1075}
I20260812 06:16:57.074453 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=10.126437
I20260812 06:16:57.177466 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.103s	user 0.015s	sys 0.016s Metrics: {"bytes_written":11692139,"delete_count":0,"lbm_write_time_us":14306,"lbm_writes_lt_1ms":288,"reinsert_count":0,"update_count":1425}
I20260812 06:16:57.178002 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=7.149875
I20260812 06:16:57.279558 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.101s	user 0.005s	sys 0.015s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":8115,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:57.280126 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=10.126437
I20260812 06:16:57.382359 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.102s	user 0.022s	sys 0.005s Metrics: {"bytes_written":11897250,"delete_count":0,"lbm_write_time_us":12290,"lbm_writes_lt_1ms":293,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1450}
I20260812 06:16:57.383004 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=7.149875
I20260812 06:16:57.484767 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.102s	user 0.010s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8178,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:57.511337 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=6.157687
I20260812 06:16:57.615845 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.104s	user 0.008s	sys 0.012s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":7236,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:57.616366 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=10.126437
I20260812 06:16:57.711854 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.095s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16033,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.712497 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=6.157687
I20260812 06:16:57.809063 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.096s	user 0.023s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12484,"lbm_writes_lt_1ms":203,"mutex_wait_us":1,"reinsert_count":0,"update_count":1000}
I20260812 06:16:57.809625 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=6.157687
I20260812 06:16:57.905735 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.096s	user 0.012s	sys 0.012s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10434,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:57.906342 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=9.134250
I20260812 06:16:57.934829 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.028s	user 0.022s	sys 0.003s Metrics: {"bytes_written":11404959,"delete_count":0,"lbm_write_time_us":11889,"lbm_writes_lt_1ms":281,"reinsert_count":0,"update_count":1390}
I20260812 06:16:57.935307 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushMRSOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=1.000000
I20260812 06:16:57.969404 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushMRSOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1849277,"cfile_init":1,"dirs.queue_time_us":213,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1172,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2398,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":45,"spinlock_wait_cycles":3968,"thread_start_us":107,"threads_started":1}
I20260812 06:16:57.970322 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling LogGCOp(7c1c959d1f5a438a8e7dc2252a417643): free 186612366 bytes of WAL
I20260812 06:16:57.970556 19744 log_reader.cc:385] T 7c1c959d1f5a438a8e7dc2252a417643: removed 18 log segments from log reader
I20260812 06:16:57.970608 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000002 (ops 7-11)
I20260812 06:16:57.970646 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000003 (ops 12-16)
I20260812 06:16:57.970677 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000004 (ops 17-21)
I20260812 06:16:57.970708 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000005 (ops 22-26)
I20260812 06:16:57.970739 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000006 (ops 27-31)
I20260812 06:16:57.970772 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000007 (ops 32-36)
I20260812 06:16:57.970800 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000008 (ops 37-41)
I20260812 06:16:57.970830 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000009 (ops 42-46)
I20260812 06:16:57.970860 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000010 (ops 47-51)
I20260812 06:16:57.970890 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000011 (ops 52-56)
I20260812 06:16:57.970937 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000012 (ops 57-60)
I20260812 06:16:57.970968 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000013 (ops 61-65)
I20260812 06:16:57.970999 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000014 (ops 66-70)
I20260812 06:16:57.971038 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000015 (ops 71-75)
I20260812 06:16:57.971067 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000016 (ops 76-80)
I20260812 06:16:57.971095 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000017 (ops 81-85)
I20260812 06:16:57.971125 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000018 (ops 86-90)
I20260812 06:16:57.971154 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000019 (ops 91-95)
I20260812 06:16:58.008670 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: LogGCOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.038s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:16:58.009109 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling UndoDeltaBlockGCOp(7c1c959d1f5a438a8e7dc2252a417643): 642 bytes on disk
I20260812 06:16:58.009563 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: UndoDeltaBlockGCOp(7c1c959d1f5a438a8e7dc2252a417643) 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:16:58.010150 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=7.149875
I20260812 06:16:58.043537 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.033s	user 0.015s	sys 0.015s Metrics: {"bytes_written":9107611,"delete_count":0,"lbm_write_time_us":11027,"lbm_writes_lt_1ms":225,"reinsert_count":0,"update_count":1110}
I20260812 06:16:58.044041 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling LogGCOp(7c1c959d1f5a438a8e7dc2252a417643): free 12017991 bytes of WAL
I20260812 06:16:58.044245 19744 log_reader.cc:385] T 7c1c959d1f5a438a8e7dc2252a417643: removed 1 log segments from log reader
I20260812 06:16:58.044292 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000020 (ops 96-100)
I20260812 06:16:58.046288 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: LogGCOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:58.046598 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=2.188937
I20260812 06:16:58.056236 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.056665 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling MajorDeltaCompactionOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=1.000000
I20260812 06:16:59.225399 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: MajorDeltaCompactionOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 1.169s	user 0.732s	sys 0.433s Metrics: {"cfile_cache_miss":4850,"cfile_cache_miss_bytes":201139632,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":20,"delta_iterators_relevant":20,"dirs.queue_time_us":1212,"lbm_read_time_us":75457,"lbm_reads_lt_1ms":4886,"lbm_write_time_us":222209,"lbm_writes_lt_1ms":4847,"peak_mem_usage":597458496,"reinsert_count":0,"spinlock_wait_cycles":73856,"thread_start_us":411,"threads_started":7,"update_count":24000}
I20260812 06:16:59.226087 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=79.579562
I20260812 06:16:59.523214 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.297s	user 0.131s	sys 0.083s Metrics: {"bytes_written":83935826,"delete_count":0,"lbm_write_time_us":94281,"lbm_writes_lt_1ms":2051,"reinsert_count":0,"update_count":10230}
I20260812 06:16:59.523809 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=25.009250
I20260812 06:16:59.709858 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.185s	user 0.047s	sys 0.012s Metrics: {"bytes_written":26830036,"delete_count":0,"lbm_write_time_us":27005,"lbm_writes_lt_1ms":657,"reinsert_count":0,"update_count":3270}
I20260812 06:16:59.710492 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=14.095187
I20260812 06:16:59.912117 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.201s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19265,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.912561 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=19.056125
I20260812 06:16:59.976127 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.063s	user 0.031s	sys 0.028s Metrics: {"bytes_written":20922554,"delete_count":0,"lbm_write_time_us":27071,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":512,"reinsert_count":0,"update_count":2550}
I20260812 06:16:59.976698 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=2.188937
I20260812 06:16:59.990372 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.990823 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=2.188937
I20260812 06:17:00.005728 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5676,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.006176 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushMRSOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=1.000000
I20260812 06:17:00.044445 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushMRSOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.038s	user 0.028s	sys 0.008s Metrics: {"bytes_written":1685374,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1214,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2217,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":41}
I20260812 06:17:00.045248 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling LogGCOp(7c1c959d1f5a438a8e7dc2252a417643): free 162576764 bytes of WAL
I20260812 06:17:00.045480 19744 log_reader.cc:385] T 7c1c959d1f5a438a8e7dc2252a417643: removed 16 log segments from log reader
I20260812 06:17:00.045532 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000021 (ops 101-105)
I20260812 06:17:00.045567 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000022 (ops 106-110)
I20260812 06:17:00.045606 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000023 (ops 111-115)
I20260812 06:17:00.045645 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000024 (ops 116-120)
I20260812 06:17:00.045686 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000025 (ops 121-125)
I20260812 06:17:00.045723 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000026 (ops 126-130)
I20260812 06:17:00.045761 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000027 (ops 131-135)
I20260812 06:17:00.045800 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000028 (ops 136-140)
I20260812 06:17:00.045837 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000029 (ops 141-144)
I20260812 06:17:00.045876 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000030 (ops 145-149)
I20260812 06:17:00.045914 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000031 (ops 150-154)
I20260812 06:17:00.045953 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000032 (ops 155-159)
I20260812 06:17:00.046001 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000033 (ops 160-164)
I20260812 06:17:00.046041 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000034 (ops 165-169)
I20260812 06:17:00.046079 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000035 (ops 170-174)
I20260812 06:17:00.046118 19744 log.cc:1079] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/7c1c959d1f5a438a8e7dc2252a417643/wal-000000036 (ops 175-179)
I20260812 06:17:00.073644 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: LogGCOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:00.074035 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=5.165500
I20260812 06:17:00.092480 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: FlushDeltaMemStoresOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":7179473,"delete_count":0,"lbm_write_time_us":7073,"lbm_writes_lt_1ms":178,"reinsert_count":0,"update_count":875}
I20260812 06:17:00.093106 19848 maintenance_manager.cc:419] P 8af08c3947e3485a9d92941dda33904f: Scheduling MajorDeltaCompactionOp(7c1c959d1f5a438a8e7dc2252a417643): perf score=1.000000
I20260812 06:17:00.529371 19549 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.609s	user 1.533s	sys 0.173s
I20260812 06:17:00.912859 19549 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.383s	user 0.002s	sys 0.001s
I20260812 06:17:00.913575 19549 tablet_server.cc:179] TabletServer@127.19.23.65:0 shutting down...
I20260812 06:17:01.019853 19744 maintenance_manager.cc:643] P 8af08c3947e3485a9d92941dda33904f: MajorDeltaCompactionOp(7c1c959d1f5a438a8e7dc2252a417643) complete. Timing: real 0.926s	user 0.531s	sys 0.395s Metrics: {"cfile_cache_miss":4014,"cfile_cache_miss_bytes":167293354,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":7,"delta_iterators_relevant":7,"dirs.queue_time_us":961,"lbm_read_time_us":65617,"lbm_reads_lt_1ms":4046,"lbm_write_time_us":147084,"lbm_writes_lt_1ms":4021,"mutex_wait_us":23,"peak_mem_usage":494939277,"reinsert_count":0,"spinlock_wait_cycles":47104,"thread_start_us":380,"threads_started":7,"update_count":19875}
I20260812 06:17:01.020443 19549 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:01.020932 19549 tablet_replica.cc:333] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f: stopping tablet replica
I20260812 06:17:01.021191 19549 raft_consensus.cc:2243] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:01.021426 19549 raft_consensus.cc:2272] T 7c1c959d1f5a438a8e7dc2252a417643 P 8af08c3947e3485a9d92941dda33904f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:01.041095 19549 tablet_server.cc:196] TabletServer@127.19.23.65:0 shutdown complete.
I20260812 06:17:01.625882 19549 master.cc:562] Master@127.19.23.126:44907 shutting down...
I20260812 06:17:01.629391 19549 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:01.629549 19549 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:01.629607 19549 tablet_replica.cc:333] T 00000000000000000000000000000000 P 65816a8c861149db9ab056d5e4db27bd: stopping tablet replica
I20260812 06:17:01.641649 19549 master.cc:584] Master@127.19.23.126:44907 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6132 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:01.734189 19549 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.23.126:44145
I20260812 06:17:01.734587 19549 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:01.736914 19914 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:01.736970 19921 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:01.736955 19916 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:01.736843 19549 server_base.cc:1061] running on GCE node
I20260812 06:17:01.737385 19549 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:01.737437 19549 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:01.737454 19549 hybrid_clock.cc:648] HybridClock initialized: now 1786515421737454 us; error 0 us; skew 500 ppm
I20260812 06:17:01.738251 19549 webserver.cc:533] Webserver started at http://127.19.23.126:40765/ using document root <none> and password file <none>
I20260812 06:17:01.738399 19549 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:01.738442 19549 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:01.738514 19549 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:01.738889 19549 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/master-0-root/instance:
uuid: "cfe543872bb646898aa20c7299e64e2a"
format_stamp: "Formatted at 2026-08-12 06:17:01 on dist-test-slave-1vmg"
I20260812 06:17:01.740433 19549 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:01.741345 19929 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:01.741591 19549 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:01.741665 19549 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/master-0-root
uuid: "cfe543872bb646898aa20c7299e64e2a"
format_stamp: "Formatted at 2026-08-12 06:17:01 on dist-test-slave-1vmg"
I20260812 06:17:01.741741 19549 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-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:01.749269 19549 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:01.749585 19549 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:01.753803 19549 rpc_server.cc:307] RPC server started. Bound to: 127.19.23.126:44145
I20260812 06:17:01.769562 20007 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.23.126:44145 every 8 connection(s)
I20260812 06:17:01.770007 20008 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:01.771807 20008 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a: Bootstrap starting.
I20260812 06:17:01.772624 20008 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:01.773581 20008 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a: No bootstrap required, opened a new log
I20260812 06:17:01.773976 20008 raft_consensus.cc:359] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cfe543872bb646898aa20c7299e64e2a" member_type: VOTER }
I20260812 06:17:01.774075 20008 raft_consensus.cc:385] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:01.774111 20008 raft_consensus.cc:740] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cfe543872bb646898aa20c7299e64e2a, State: Initialized, Role: FOLLOWER
I20260812 06:17:01.774259 20008 consensus_queue.cc:260] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [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: "cfe543872bb646898aa20c7299e64e2a" member_type: VOTER }
I20260812 06:17:01.774335 20008 raft_consensus.cc:399] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:01.774380 20008 raft_consensus.cc:493] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:01.774436 20008 raft_consensus.cc:3060] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:01.775161 20008 raft_consensus.cc:515] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cfe543872bb646898aa20c7299e64e2a" member_type: VOTER }
I20260812 06:17:01.775301 20008 leader_election.cc:304] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [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: cfe543872bb646898aa20c7299e64e2a; no voters: 
I20260812 06:17:01.775489 20008 leader_election.cc:290] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:01.775597 20013 raft_consensus.cc:2804] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:01.775790 20013 raft_consensus.cc:697] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 1 LEADER]: Becoming Leader. State: Replica: cfe543872bb646898aa20c7299e64e2a, State: Running, Role: LEADER
I20260812 06:17:01.775938 20008 sys_catalog.cc:565] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:01.775918 20013 consensus_queue.cc:237] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [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: "cfe543872bb646898aa20c7299e64e2a" member_type: VOTER }
I20260812 06:17:01.776407 20014 sys_catalog.cc:455] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "cfe543872bb646898aa20c7299e64e2a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cfe543872bb646898aa20c7299e64e2a" member_type: VOTER } }
I20260812 06:17:01.776443 20015 sys_catalog.cc:455] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [sys.catalog]: SysCatalogTable state changed. Reason: New leader cfe543872bb646898aa20c7299e64e2a. Latest consensus state: current_term: 1 leader_uuid: "cfe543872bb646898aa20c7299e64e2a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cfe543872bb646898aa20c7299e64e2a" member_type: VOTER } }
I20260812 06:17:01.776517 20014 sys_catalog.cc:458] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:01.776525 20015 sys_catalog.cc:458] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:01.776991 20021 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:01.777815 20021 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:01.777987 19549 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:01.779595 20021 catalog_manager.cc:1383] Generated new cluster ID: afd10bf5d7c0419987c9099aa1a5e598
I20260812 06:17:01.779645 20021 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:01.805027 20021 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:01.805552 20021 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:01.814033 20021 catalog_manager.cc:6092] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a: Generated new TSK 0
I20260812 06:17:01.814172 20021 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:01.842334 19549 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:01.844172 20046 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:01.844209 20049 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:01.844282 19549 server_base.cc:1061] running on GCE node
W20260812 06:17:01.844343 20047 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:01.844539 19549 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:01.844585 19549 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:01.844599 19549 hybrid_clock.cc:648] HybridClock initialized: now 1786515421844599 us; error 0 us; skew 500 ppm
I20260812 06:17:01.845373 19549 webserver.cc:533] Webserver started at http://127.19.23.65:39727/ using document root <none> and password file <none>
I20260812 06:17:01.845520 19549 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:01.845570 19549 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:01.845644 19549 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:01.845992 19549 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/instance:
uuid: "b356d341be604e3184b18432b60adbad"
format_stamp: "Formatted at 2026-08-12 06:17:01 on dist-test-slave-1vmg"
I20260812 06:17:01.847447 19549 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:01.848296 20061 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:01.848503 19549 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:01.848567 19549 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root
uuid: "b356d341be604e3184b18432b60adbad"
format_stamp: "Formatted at 2026-08-12 06:17:01 on dist-test-slave-1vmg"
I20260812 06:17:01.848631 19549 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-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:01.861572 19549 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:01.861896 19549 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:01.862157 19549 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:01.862584 19549 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:01.862622 19549 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:01.862654 19549 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:01.862682 19549 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:01.866906 19549 rpc_server.cc:307] RPC server started. Bound to: 127.19.23.65:34963
I20260812 06:17:01.866978 20170 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.23.65:34963 every 8 connection(s)
I20260812 06:17:01.874025 20173 heartbeater.cc:344] Connected to a master server at 127.19.23.126:44145
I20260812 06:17:01.874109 20173 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:01.874290 20173 heartbeater.cc:507] Master 127.19.23.126:44145 requested a full tablet report, sending...
I20260812 06:17:01.874835 19954 ts_manager.cc:194] Registered new tserver with Master: b356d341be604e3184b18432b60adbad (127.19.23.65:34963)
I20260812 06:17:01.874980 19549 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007659812s
I20260812 06:17:01.875617 19954 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34572
I20260812 06:17:01.881268 19954 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34582:
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:01.888996 20109 tablet_service.cc:1511] Processing CreateTablet for tablet 3ec27628d3044ef595e5e1eee391a445 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a21570280bce430192bdd82ff8694375]), partition=
I20260812 06:17:01.889241 20109 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3ec27628d3044ef595e5e1eee391a445. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:01.890962 20199 tablet_bootstrap.cc:492] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Bootstrap starting.
I20260812 06:17:01.891789 20199 tablet_bootstrap.cc:654] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:01.892668 20199 tablet_bootstrap.cc:492] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: No bootstrap required, opened a new log
I20260812 06:17:01.892747 20199 ts_tablet_manager.cc:1403] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:01.893079 20199 raft_consensus.cc:359] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b356d341be604e3184b18432b60adbad" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 34963 } }
I20260812 06:17:01.893160 20199 raft_consensus.cc:385] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:01.893190 20199 raft_consensus.cc:740] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b356d341be604e3184b18432b60adbad, State: Initialized, Role: FOLLOWER
I20260812 06:17:01.893311 20199 consensus_queue.cc:260] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [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: "b356d341be604e3184b18432b60adbad" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 34963 } }
I20260812 06:17:01.893378 20199 raft_consensus.cc:399] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:01.893409 20199 raft_consensus.cc:493] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:01.893456 20199 raft_consensus.cc:3060] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:01.894120 20199 raft_consensus.cc:515] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b356d341be604e3184b18432b60adbad" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 34963 } }
I20260812 06:17:01.894243 20199 leader_election.cc:304] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [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: b356d341be604e3184b18432b60adbad; no voters: 
I20260812 06:17:01.894425 20199 leader_election.cc:290] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:01.894662 20202 raft_consensus.cc:2804] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:01.894735 20199 ts_tablet_manager.cc:1434] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:01.894742 20173 heartbeater.cc:499] Master 127.19.23.126:44145 was elected leader, sending a full tablet report...
I20260812 06:17:01.894954 20202 raft_consensus.cc:697] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 1 LEADER]: Becoming Leader. State: Replica: b356d341be604e3184b18432b60adbad, State: Running, Role: LEADER
I20260812 06:17:01.895090 20202 consensus_queue.cc:237] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [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: "b356d341be604e3184b18432b60adbad" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 34963 } }
I20260812 06:17:01.896248 19954 catalog_manager.cc:5719] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad reported cstate change: term changed from 0 to 1, leader changed from <none> to b356d341be604e3184b18432b60adbad (127.19.23.65). New cstate: current_term: 1 leader_uuid: "b356d341be604e3184b18432b60adbad" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b356d341be604e3184b18432b60adbad" member_type: VOTER last_known_addr { host: "127.19.23.65" port: 34963 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:01.947388 19549 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.047s	user 0.016s	sys 0.005s
I20260812 06:17:02.117978 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushMRSOp(3ec27628d3044ef595e5e1eee391a445): perf score=23.023690
I20260812 06:17:02.279064 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushMRSOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.161s	user 0.128s	sys 0.032s Metrics: {"bytes_written":13333098,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":907,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43104,"lbm_writes_lt_1ms":882,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":19328,"update_count":1625}
I20260812 06:17:02.279862 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling LogGCOp(3ec27628d3044ef595e5e1eee391a445): free 20743880 bytes of WAL
I20260812 06:17:02.280117 20071 log_reader.cc:385] T 3ec27628d3044ef595e5e1eee391a445: removed 2 log segments from log reader
I20260812 06:17:02.280196 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000001 (ops 1-6)
I20260812 06:17:02.280283 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000002 (ops 7-11)
I20260812 06:17:02.284708 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: LogGCOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:02.285054 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.196750
I20260812 06:17:02.299005 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.014s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":2875,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:17:02.299319 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:02.308480 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.308823 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:02.481055 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.172s	user 0.113s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815782,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":495,"lbm_read_time_us":11117,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27216,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":315,"threads_started":5,"update_count":2500}
I20260812 06:17:02.481573 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:02.526798 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.045s	user 0.024s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17416,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.527383 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445): 20513814 bytes on disk
I20260812 06:17:02.527817 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.528265 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:02.543476 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.543896 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:02.681775 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.138s	user 0.109s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1527,"lbm_read_time_us":9514,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26406,"lbm_writes_lt_1ms":543,"mutex_wait_us":539,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:02.682336 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=11.118625
I20260812 06:17:02.723492 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.041s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15358,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:02.723917 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:02.744935 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6013,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:02.745440 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:02.755861 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.756306 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:02.929060 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.173s	user 0.130s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":288,"lbm_read_time_us":12015,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32242,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:17:02.929595 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:02.983695 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.053s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20593,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.984172 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:02.993790 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.994319 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:03.132460 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.137s	user 0.105s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":8795,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27094,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.132985 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=11.118625
I20260812 06:17:03.175462 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.042s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15411,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:03.176055 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:03.201385 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.201851 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:03.211208 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3515,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.211664 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:03.364756 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.153s	user 0.105s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":907,"lbm_read_time_us":11704,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25013,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:03.365309 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=12.110812
I20260812 06:17:03.402659 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.037s	user 0.017s	sys 0.016s Metrics: {"bytes_written":14358698,"delete_count":0,"lbm_write_time_us":15880,"lbm_writes_lt_1ms":353,"reinsert_count":0,"update_count":1750}
I20260812 06:17:03.403251 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.196750
I20260812 06:17:03.411450 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2461658,"delete_count":0,"lbm_write_time_us":2673,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:17:03.411803 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushMRSOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:03.466235 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushMRSOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.054s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1259,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1524,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:03.466849 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling LogGCOp(3ec27628d3044ef595e5e1eee391a445): free 121006434 bytes of WAL
I20260812 06:17:03.467074 20071 log_reader.cc:385] T 3ec27628d3044ef595e5e1eee391a445: removed 12 log segments from log reader
I20260812 06:17:03.467126 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000003 (ops 12-16)
I20260812 06:17:03.467156 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000004 (ops 17-20)
I20260812 06:17:03.467190 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000005 (ops 21-25)
I20260812 06:17:03.467224 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000006 (ops 26-30)
I20260812 06:17:03.467257 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000007 (ops 31-35)
I20260812 06:17:03.467288 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000008 (ops 36-40)
I20260812 06:17:03.467321 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000009 (ops 41-45)
I20260812 06:17:03.467353 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000010 (ops 46-50)
I20260812 06:17:03.467384 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000011 (ops 51-55)
I20260812 06:17:03.467417 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000012 (ops 56-60)
I20260812 06:17:03.467448 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000013 (ops 61-65)
I20260812 06:17:03.467480 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000014 (ops 66-70)
I20260812 06:17:03.488356 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: LogGCOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:03.488741 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=6.157687
I20260812 06:17:03.515349 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.026s	user 0.017s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10565,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:03.515794 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:03.529805 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.530282 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:03.744240 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.214s	user 0.144s	sys 0.070s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020712,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":135,"lbm_read_time_us":15088,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35853,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11264,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:17:03.744786 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445): 472 bytes on disk
I20260812 06:17:03.745221 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.745747 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=18.063937
I20260812 06:17:03.800760 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.055s	user 0.029s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24208,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.801489 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:03.817487 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.817896 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:03.973181 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.155s	user 0.116s	sys 0.038s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1054,"lbm_read_time_us":10670,"lbm_reads_lt_1ms":664,"lbm_write_time_us":29355,"lbm_writes_lt_1ms":643,"mutex_wait_us":516,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:17:03.973731 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:04.030041 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.056s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24956,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.030606 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=3.181125
I20260812 06:17:04.048990 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.018s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.049427 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:04.061805 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4750,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.062180 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:04.216300 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.154s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1001,"lbm_read_time_us":11384,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30686,"lbm_writes_lt_1ms":643,"mutex_wait_us":301,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:17:04.216799 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:04.256171 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.039s	user 0.030s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16880,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.256644 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:04.271833 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.272385 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:04.429522 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.157s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1012,"lbm_read_time_us":9932,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27783,"lbm_writes_lt_1ms":543,"mutex_wait_us":328,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:04.430063 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:04.473802 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.044s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17268,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:04.474313 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:04.621526 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.147s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713155,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":122,"lbm_read_time_us":10380,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24302,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.622078 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:04.666208 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.041s	user 0.027s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16925,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:04.666682 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:04.676764 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.677413 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushMRSOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:04.712355 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushMRSOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.035s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1249,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1338,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:04.712963 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling LogGCOp(3ec27628d3044ef595e5e1eee391a445): free 124257253 bytes of WAL
I20260812 06:17:04.713178 20071 log_reader.cc:385] T 3ec27628d3044ef595e5e1eee391a445: removed 12 log segments from log reader
I20260812 06:17:04.713227 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000015 (ops 71-75)
I20260812 06:17:04.713254 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000016 (ops 76-80)
I20260812 06:17:04.713285 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000017 (ops 81-85)
I20260812 06:17:04.713317 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000018 (ops 86-90)
I20260812 06:17:04.713343 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000019 (ops 91-94)
I20260812 06:17:04.713374 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000020 (ops 95-99)
I20260812 06:17:04.713406 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000021 (ops 100-104)
I20260812 06:17:04.713438 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000022 (ops 105-109)
I20260812 06:17:04.713469 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000023 (ops 110-114)
I20260812 06:17:04.713501 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000024 (ops 115-119)
I20260812 06:17:04.713532 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000025 (ops 120-124)
I20260812 06:17:04.713574 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000026 (ops 125-129)
I20260812 06:17:04.736053 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: LogGCOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.023s	user 0.001s	sys 0.021s Metrics: {}
I20260812 06:17:04.736397 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=3.181125
I20260812 06:17:04.757743 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.021s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.758157 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:04.766817 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3174,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.767211 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445): 447 bytes on disk
I20260812 06:17:04.767591 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445) 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:04.768031 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:04.982492 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.214s	user 0.122s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":720,"lbm_read_time_us":14483,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33153,"lbm_writes_lt_1ms":743,"mutex_wait_us":353,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:17:04.983103 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=18.063937
I20260812 06:17:05.036370 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.050s	user 0.022s	sys 0.027s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":22208,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:05.036942 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:05.052227 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.052649 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:05.234254 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.181s	user 0.113s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":673,"lbm_read_time_us":13410,"lbm_reads_lt_1ms":672,"lbm_write_time_us":28740,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:05.238320 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:05.294658 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.056s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27174,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.295228 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:05.305745 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.306329 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:05.462941 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.156s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":11392,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24709,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":40064,"update_count":2500}
I20260812 06:17:05.463491 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:05.526115 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.062s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20461,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.526675 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:05.541682 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.542222 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:05.710984 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.169s	user 0.115s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":760,"lbm_read_time_us":13483,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29800,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:17:05.711637 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:05.762523 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.051s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17878,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.763029 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:05.778420 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.779022 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:05.956269 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.177s	user 0.129s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":572,"lbm_read_time_us":12819,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27402,"lbm_writes_lt_1ms":543,"mutex_wait_us":260,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:17:05.956845 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=14.095187
I20260812 06:17:06.006943 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.050s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17880,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.007393 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:06.016872 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.017258 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushMRSOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:06.055701 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushMRSOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.038s	user 0.020s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1258,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1348,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:06.056314 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling LogGCOp(3ec27628d3044ef595e5e1eee391a445): free 112239502 bytes of WAL
I20260812 06:17:06.056519 20071 log_reader.cc:385] T 3ec27628d3044ef595e5e1eee391a445: removed 11 log segments from log reader
I20260812 06:17:06.056565 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000027 (ops 130-134)
I20260812 06:17:06.056592 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000028 (ops 135-139)
I20260812 06:17:06.056622 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000029 (ops 140-144)
I20260812 06:17:06.056653 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000030 (ops 145-148)
I20260812 06:17:06.056686 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000031 (ops 149-153)
I20260812 06:17:06.056718 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000032 (ops 154-158)
I20260812 06:17:06.056751 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000033 (ops 159-163)
I20260812 06:17:06.056783 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000034 (ops 164-168)
I20260812 06:17:06.056815 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000035 (ops 169-173)
I20260812 06:17:06.056846 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000036 (ops 174-178)
I20260812 06:17:06.056878 20071 log.cc:1079] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: Deleting log segment in path: /tmp/dist-test-taskcQIUkP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515415572524-19549-0/minicluster-data/ts-0-root/wals/3ec27628d3044ef595e5e1eee391a445/wal-000000037 (ops 179-183)
I20260812 06:17:06.076051 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: LogGCOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.020s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:06.076414 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445): 447 bytes on disk
I20260812 06:17:06.076833 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: UndoDeltaBlockGCOp(3ec27628d3044ef595e5e1eee391a445) 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:06.077340 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:06.098284 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.021s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.098694 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:06.108446 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3701,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.108855 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:06.331688 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.223s	user 0.152s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2292,"lbm_read_time_us":14657,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35470,"lbm_writes_lt_1ms":743,"mutex_wait_us":1704,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":38272,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:17:06.332262 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=18.063937
I20260812 06:17:06.392331 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.060s	user 0.019s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23376,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:06.392839 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445): perf score=2.188937
I20260812 06:17:06.406812 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: FlushDeltaMemStoresOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.407219 20174 maintenance_manager.cc:419] P b356d341be604e3184b18432b60adbad: Scheduling MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445): perf score=1.000000
I20260812 06:17:06.442310 19549 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.495s	user 1.618s	sys 0.200s
I20260812 06:17:06.530102 19549 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.001s	sys 0.000s
I20260812 06:17:06.530584 19549 tablet_server.cc:179] TabletServer@127.19.23.65:0 shutting down...
I20260812 06:17:06.586838 20071 maintenance_manager.cc:643] P b356d341be604e3184b18432b60adbad: MajorDeltaCompactionOp(3ec27628d3044ef595e5e1eee391a445) complete. Timing: real 0.179s	user 0.107s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":15236,"lbm_reads_lt_1ms":668,"lbm_write_time_us":28867,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":3000}
I20260812 06:17:06.587462 19549 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:06.587751 19549 tablet_replica.cc:333] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad: stopping tablet replica
I20260812 06:17:06.587883 19549 raft_consensus.cc:2243] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:06.588042 19549 raft_consensus.cc:2272] T 3ec27628d3044ef595e5e1eee391a445 P b356d341be604e3184b18432b60adbad [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:06.601995 19549 tablet_server.cc:196] TabletServer@127.19.23.65:0 shutdown complete.
I20260812 06:17:06.638346 19549 master.cc:562] Master@127.19.23.126:44145 shutting down...
I20260812 06:17:06.641242 19549 raft_consensus.cc:2243] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:06.641405 19549 raft_consensus.cc:2272] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:06.641479 19549 tablet_replica.cc:333] T 00000000000000000000000000000000 P cfe543872bb646898aa20c7299e64e2a: stopping tablet replica
I20260812 06:17:06.653580 19549 master.cc:584] Master@127.19.23.126:44145 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5014 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11148 ms total)

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