[==========] 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:40.727046  8128 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.240.62:45499
I20260812 06:16:40.727937  8128 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:40.728473  8128 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.734076  8137 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:40.734138  8140 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:40.734302  8128 server_base.cc:1061] running on GCE node
W20260812 06:16:40.734375  8138 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:40.734791  8128 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.734879  8128 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:40.734920  8128 hybrid_clock.cc:648] HybridClock initialized: now 1786515400734917 us; error 0 us; skew 500 ppm
I20260812 06:16:40.736454  8128 webserver.cc:533] Webserver started at http://127.7.240.62:35691/ using document root <none> and password file <none>
I20260812 06:16:40.736948  8128 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.737005  8128 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.737223  8128 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.738741  8128 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/master-0-root/instance:
uuid: "b10dc34024a84a21b95f12de57357d6f"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-42z9"
I20260812 06:16:40.741854  8128 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:40.743737  8149 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:40.744607  8128 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:40.744709  8128 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/master-0-root
uuid: "b10dc34024a84a21b95f12de57357d6f"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-42z9"
I20260812 06:16:40.744791  8128 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-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:40.761227  8128 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.761755  8128 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:40.761891  8128 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.768429  8128 rpc_server.cc:307] RPC server started. Bound to: 127.7.240.62:45499
I20260812 06:16:40.768474  8222 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.240.62:45499 every 8 connection(s)
I20260812 06:16:40.770429  8223 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:40.775296  8223 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f: Bootstrap starting.
I20260812 06:16:40.777367  8223 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.778183  8223 log.cc:826] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:40.779611  8223 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f: No bootstrap required, opened a new log
I20260812 06:16:40.782184  8223 raft_consensus.cc:359] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b10dc34024a84a21b95f12de57357d6f" member_type: VOTER }
I20260812 06:16:40.782331  8223 raft_consensus.cc:385] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.782397  8223 raft_consensus.cc:740] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b10dc34024a84a21b95f12de57357d6f, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.782902  8223 consensus_queue.cc:260] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [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: "b10dc34024a84a21b95f12de57357d6f" member_type: VOTER }
I20260812 06:16:40.783047  8223 raft_consensus.cc:399] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.783110  8223 raft_consensus.cc:493] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.783223  8223 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.783901  8223 raft_consensus.cc:515] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b10dc34024a84a21b95f12de57357d6f" member_type: VOTER }
I20260812 06:16:40.784283  8223 leader_election.cc:304] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [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: b10dc34024a84a21b95f12de57357d6f; no voters: 
I20260812 06:16:40.784539  8223 leader_election.cc:290] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.784667  8228 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.784860  8228 raft_consensus.cc:697] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 1 LEADER]: Becoming Leader. State: Replica: b10dc34024a84a21b95f12de57357d6f, State: Running, Role: LEADER
I20260812 06:16:40.785225  8228 consensus_queue.cc:237] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [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: "b10dc34024a84a21b95f12de57357d6f" member_type: VOTER }
I20260812 06:16:40.785392  8223 sys_catalog.cc:565] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:40.786912  8237 sys_catalog.cc:455] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [sys.catalog]: SysCatalogTable state changed. Reason: New leader b10dc34024a84a21b95f12de57357d6f. Latest consensus state: current_term: 1 leader_uuid: "b10dc34024a84a21b95f12de57357d6f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b10dc34024a84a21b95f12de57357d6f" member_type: VOTER } }
I20260812 06:16:40.786955  8231 sys_catalog.cc:455] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b10dc34024a84a21b95f12de57357d6f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b10dc34024a84a21b95f12de57357d6f" member_type: VOTER } }
I20260812 06:16:40.787036  8237 sys_catalog.cc:458] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.787042  8231 sys_catalog.cc:458] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.787509  8128 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:40.787561  8255 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:40.789573  8255 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:40.793324  8255 catalog_manager.cc:1383] Generated new cluster ID: 0fcdbcbd11ad4d77933f166b3a8ee6e2
I20260812 06:16:40.793385  8255 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:40.801673  8255 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:40.802388  8255 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:40.808573  8255 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f: Generated new TSK 0
I20260812 06:16:40.809042  8255 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:40.820281  8128 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.822742  8263 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:40.822829  8267 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:16:40.822830  8264 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:40.823066  8128 server_base.cc:1061] running on GCE node
I20260812 06:16:40.823231  8128 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.823271  8128 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:40.823285  8128 hybrid_clock.cc:648] HybridClock initialized: now 1786515400823286 us; error 0 us; skew 500 ppm
I20260812 06:16:40.824056  8128 webserver.cc:533] Webserver started at http://127.7.240.1:36433/ using document root <none> and password file <none>
I20260812 06:16:40.824203  8128 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.824250  8128 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.824321  8128 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.824647  8128 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/instance:
uuid: "b3492c71a3a746d8b8bf69307149fc3b"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-42z9"
I20260812 06:16:40.826079  8128 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:40.826977  8274 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:40.827212  8128 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:40.827279  8128 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root
uuid: "b3492c71a3a746d8b8bf69307149fc3b"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-42z9"
I20260812 06:16:40.827342  8128 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-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:40.858915  8128 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.859277  8128 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.859683  8128 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:40.860504  8128 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:40.860601  8128 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.860694  8128 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:40.860731  8128 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.866937  8128 rpc_server.cc:307] RPC server started. Bound to: 127.7.240.1:34323
I20260812 06:16:40.866978  8372 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.240.1:34323 every 8 connection(s)
I20260812 06:16:40.875459  8373 heartbeater.cc:344] Connected to a master server at 127.7.240.62:45499
I20260812 06:16:40.875669  8373 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:40.876032  8373 heartbeater.cc:507] Master 127.7.240.62:45499 requested a full tablet report, sending...
I20260812 06:16:40.877259  8172 ts_manager.cc:194] Registered new tserver with Master: b3492c71a3a746d8b8bf69307149fc3b (127.7.240.1:34323)
I20260812 06:16:40.877544  8128 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010045237s
I20260812 06:16:40.878389  8172 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45706
I20260812 06:16:40.885334  8172 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45708:
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:40.897404  8319 tablet_service.cc:1511] Processing CreateTablet for tablet c3d08d72cc0f48509df49776805ced6a (DEFAULT_TABLE table=heavy-update-compaction-test [id=ce9aaa6999ea463a9c4ee327d438ba8e]), partition=
I20260812 06:16:40.897830  8319 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c3d08d72cc0f48509df49776805ced6a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.899946  8396 tablet_bootstrap.cc:492] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Bootstrap starting.
I20260812 06:16:40.901029  8396 tablet_bootstrap.cc:654] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.902230  8396 tablet_bootstrap.cc:492] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: No bootstrap required, opened a new log
I20260812 06:16:40.902328  8396 ts_tablet_manager.cc:1403] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:40.902792  8396 raft_consensus.cc:359] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3492c71a3a746d8b8bf69307149fc3b" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34323 } }
I20260812 06:16:40.902905  8396 raft_consensus.cc:385] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.902943  8396 raft_consensus.cc:740] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b3492c71a3a746d8b8bf69307149fc3b, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.903069  8396 consensus_queue.cc:260] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [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: "b3492c71a3a746d8b8bf69307149fc3b" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34323 } }
I20260812 06:16:40.903156  8396 raft_consensus.cc:399] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.903239  8396 raft_consensus.cc:493] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.903293  8396 raft_consensus.cc:3060] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.904172  8396 raft_consensus.cc:515] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3492c71a3a746d8b8bf69307149fc3b" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34323 } }
I20260812 06:16:40.904316  8396 leader_election.cc:304] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [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: b3492c71a3a746d8b8bf69307149fc3b; no voters: 
I20260812 06:16:40.904495  8396 leader_election.cc:290] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.904613  8400 raft_consensus.cc:2804] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.904803  8396 ts_tablet_manager.cc:1434] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:40.905155  8400 raft_consensus.cc:697] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 1 LEADER]: Becoming Leader. State: Replica: b3492c71a3a746d8b8bf69307149fc3b, State: Running, Role: LEADER
I20260812 06:16:40.905185  8373 heartbeater.cc:499] Master 127.7.240.62:45499 was elected leader, sending a full tablet report...
I20260812 06:16:40.905620  8400 consensus_queue.cc:237] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [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: "b3492c71a3a746d8b8bf69307149fc3b" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34323 } }
I20260812 06:16:40.908110  8172 catalog_manager.cc:5719] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b reported cstate change: term changed from 0 to 1, leader changed from <none> to b3492c71a3a746d8b8bf69307149fc3b (127.7.240.1). New cstate: current_term: 1 leader_uuid: "b3492c71a3a746d8b8bf69307149fc3b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3492c71a3a746d8b8bf69307149fc3b" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34323 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:40.970743  8128 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.011s	sys 0.013s
I20260812 06:16:41.117882  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushMRSOp(c3d08d72cc0f48509df49776805ced6a): perf score=23.023690
I20260812 06:16:41.299571  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushMRSOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.181s	user 0.115s	sys 0.052s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":195,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":683,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44416,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":125,"threads_started":1,"update_count":1500}
I20260812 06:16:41.300633  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling LogGCOp(c3d08d72cc0f48509df49776805ced6a): free 20743880 bytes of WAL
I20260812 06:16:41.300916  8282 log_reader.cc:385] T c3d08d72cc0f48509df49776805ced6a: removed 2 log segments from log reader
I20260812 06:16:41.300978  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000001 (ops 1-6)
I20260812 06:16:41.301035  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000002 (ops 7-11)
I20260812 06:16:41.304593  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: LogGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:41.304847  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:41.314636  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.314956  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:41.453842  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.139s	user 0.085s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":723,"lbm_read_time_us":9259,"lbm_reads_lt_1ms":468,"lbm_write_time_us":19594,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":297,"threads_started":5,"update_count":2000}
I20260812 06:16:41.454285  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a): 20513814 bytes on disk
I20260812 06:16:41.454721  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.455117  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:41.500867  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.046s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15276,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.501312  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:41.510653  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.006s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.511067  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:41.625763  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.114s	user 0.099s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":8848,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19632,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":2000}
I20260812 06:16:41.626279  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:41.682335  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.056s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":37353,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.682822  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:41.697995  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5600,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.698693  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:41.815613  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.117s	user 0.099s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":540,"lbm_read_time_us":8799,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21314,"lbm_writes_lt_1ms":443,"mutex_wait_us":256,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:16:41.816186  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:41.859475  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.043s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14495,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.860044  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:41.869609  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.870030  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:42.007498  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.137s	user 0.077s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1026,"lbm_read_time_us":9233,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22679,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.008031  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:42.052161  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.044s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14422,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.052613  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:42.067166  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.067709  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:42.180392  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.112s	user 0.093s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":7540,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21200,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.180836  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:42.218063  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.037s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12501,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.218537  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:42.228055  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.228463  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:42.344527  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.116s	user 0.080s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":576,"lbm_read_time_us":8900,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20680,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:16:42.344913  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:42.390208  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.045s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15073,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.390672  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:42.405211  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.405687  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushMRSOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:42.444489  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushMRSOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.039s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":971,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1466,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:42.445366  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling LogGCOp(c3d08d72cc0f48509df49776805ced6a): free 115943172 bytes of WAL
I20260812 06:16:42.445614  8282 log_reader.cc:385] T c3d08d72cc0f48509df49776805ced6a: removed 11 log segments from log reader
I20260812 06:16:42.445662  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000003 (ops 12-16)
I20260812 06:16:42.445698  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000004 (ops 17-21)
I20260812 06:16:42.445729  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000005 (ops 22-26)
I20260812 06:16:42.445760  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000006 (ops 27-31)
I20260812 06:16:42.445785  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000007 (ops 32-37)
I20260812 06:16:42.445815  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000008 (ops 38-42)
I20260812 06:16:42.445845  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000009 (ops 43-47)
I20260812 06:16:42.445875  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000010 (ops 48-52)
I20260812 06:16:42.445905  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000011 (ops 53-57)
I20260812 06:16:42.445935  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000012 (ops 58-62)
I20260812 06:16:42.445964  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000013 (ops 63-66)
I20260812 06:16:42.464720  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: LogGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.019s	user 0.000s	sys 0.016s Metrics: {}
I20260812 06:16:42.465255  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a): 448 bytes on disk
I20260812 06:16:42.465698  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.466144  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=3.181125
I20260812 06:16:42.486292  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:42.486732  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:42.495576  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3246,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.495957  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:42.684772  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.189s	user 0.118s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2993,"lbm_read_time_us":13007,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30884,"lbm_writes_lt_1ms":643,"mutex_wait_us":2347,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:16:42.685240  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:42.722667  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.037s	user 0.033s	sys 0.003s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16446,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.723196  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:42.855329  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.132s	user 0.080s	sys 0.050s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713155,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":168,"lbm_read_time_us":10195,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21180,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":71424,"update_count":2000}
I20260812 06:16:42.855779  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=11.118625
I20260812 06:16:42.884268  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.028s	user 0.021s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12023,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:42.884814  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:42.895857  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3630,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.896265  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.018303  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.122s	user 0.095s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":7494,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23696,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:16:43.018781  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:43.060550  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.042s	user 0.021s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11912,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.061086  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:43.070647  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.071153  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.187215  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.116s	user 0.096s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":7564,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22442,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:16:43.187664  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:43.220701  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.033s	user 0.016s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13085,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.221119  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:43.232334  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4097,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.232939  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.346336  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.113s	user 0.088s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":559,"lbm_read_time_us":7360,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19863,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:16:43.347045  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:43.381755  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.034s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12445,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.382211  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:43.391919  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.392470  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.524611  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.132s	user 0.091s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":10611,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21954,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:16:43.525202  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:43.571322  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.046s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15350,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.571779  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:43.581295  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.581786  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.690980  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.109s	user 0.077s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":8247,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19704,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:16:43.691493  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=10.126437
I20260812 06:16:43.726291  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.035s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12751,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.726797  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:43.736593  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.737056  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushMRSOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.768321  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushMRSOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1049,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1400,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:43.768951  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling LogGCOp(c3d08d72cc0f48509df49776805ced6a): free 121006432 bytes of WAL
I20260812 06:16:43.769157  8282 log_reader.cc:385] T c3d08d72cc0f48509df49776805ced6a: removed 12 log segments from log reader
I20260812 06:16:43.769202  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000014 (ops 67-71)
I20260812 06:16:43.769229  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000015 (ops 72-76)
I20260812 06:16:43.769259  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000016 (ops 77-81)
I20260812 06:16:43.769290  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000017 (ops 82-86)
I20260812 06:16:43.769322  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000018 (ops 87-91)
I20260812 06:16:43.769356  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000019 (ops 92-96)
I20260812 06:16:43.769388  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000020 (ops 97-101)
I20260812 06:16:43.769420  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000021 (ops 102-106)
I20260812 06:16:43.769476  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000022 (ops 107-111)
I20260812 06:16:43.769516  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000023 (ops 112-116)
I20260812 06:16:43.769549  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000024 (ops 117-120)
I20260812 06:16:43.769580  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000025 (ops 121-125)
I20260812 06:16:43.791005  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: LogGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.022s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:16:43.791508  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=3.181125
I20260812 06:16:43.802687  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:43.803092  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:43.815582  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4849,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.815994  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a): 472 bytes on disk
I20260812 06:16:43.816509  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.817034  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:43.985335  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.168s	user 0.108s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1887,"lbm_read_time_us":10772,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30968,"lbm_writes_lt_1ms":643,"mutex_wait_us":522,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:16:43.985915  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:44.028226  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.042s	user 0.019s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16355,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.028628  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:44.039291  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.040642  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:44.185575  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.145s	user 0.114s	sys 0.015s 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":532,"lbm_read_time_us":8395,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25401,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73984,"update_count":2500}
I20260812 06:16:44.186076  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:44.237291  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.051s	user 0.022s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17884,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.237864  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:44.247512  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.248027  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:44.404023  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.156s	user 0.095s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":881,"lbm_read_time_us":11113,"lbm_reads_lt_1ms":572,"lbm_write_time_us":23535,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23296,"update_count":2500}
I20260812 06:16:44.404618  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:44.462433  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.058s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25254,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.462994  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:44.472529  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3545,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.473086  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:44.620590  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.147s	user 0.111s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":540,"lbm_read_time_us":11355,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24326,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:16:44.621129  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:44.674983  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.054s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16873,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.675495  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:44.690292  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.690737  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:44.845631  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.155s	user 0.108s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":954,"lbm_read_time_us":11429,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25981,"lbm_writes_lt_1ms":543,"mutex_wait_us":170,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.846071  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=11.118625
I20260812 06:16:44.881466  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.035s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14994,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:44.881959  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:44.897022  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5194,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.897543  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:45.041520  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.144s	user 0.096s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":98,"lbm_read_time_us":8105,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21759,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:16:45.042150  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:45.095675  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.053s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25388,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.096204  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=2.188937
I20260812 06:16:45.107322  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.107770  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushMRSOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:45.138866  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushMRSOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1128,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1351,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:45.139519  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling LogGCOp(c3d08d72cc0f48509df49776805ced6a): free 133024632 bytes of WAL
I20260812 06:16:45.139745  8282 log_reader.cc:385] T c3d08d72cc0f48509df49776805ced6a: removed 13 log segments from log reader
I20260812 06:16:45.139792  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000026 (ops 126-130)
I20260812 06:16:45.139819  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000027 (ops 131-135)
I20260812 06:16:45.139848  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000028 (ops 136-140)
I20260812 06:16:45.139879  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000029 (ops 141-145)
I20260812 06:16:45.139910  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000030 (ops 146-150)
I20260812 06:16:45.139940  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000031 (ops 151-154)
I20260812 06:16:45.139971  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000032 (ops 155-159)
I20260812 06:16:45.139999  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000033 (ops 160-164)
I20260812 06:16:45.140023  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000034 (ops 165-169)
I20260812 06:16:45.140053  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000035 (ops 170-174)
I20260812 06:16:45.140082  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000036 (ops 175-179)
I20260812 06:16:45.140110  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000037 (ops 180-184)
I20260812 06:16:45.140136  8282 log.cc:1079] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/c3d08d72cc0f48509df49776805ced6a/wal-000000038 (ops 185-189)
I20260812 06:16:45.165223  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: LogGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:45.165680  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=5.165500
I20260812 06:16:45.194289  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.028s	user 0.024s	sys 0.004s Metrics: {"bytes_written":7056401,"delete_count":0,"lbm_write_time_us":8435,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:16:45.194743  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:45.199472  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.005s	user 0.003s	sys 0.000s Metrics: {"bytes_written":1148852,"delete_count":0,"lbm_write_time_us":1156,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:16:45.199851  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a): 482 bytes on disk
I20260812 06:16:45.200197  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: UndoDeltaBlockGCOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.200749  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:45.383464  8128 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.413s	user 1.652s	sys 0.126s
I20260812 06:16:45.405244  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.204s	user 0.131s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020676,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14889,"lbm_reads_lt_1ms":762,"lbm_write_time_us":35419,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:16:45.405753  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a): perf score=14.095187
I20260812 06:16:45.435227  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: FlushDeltaMemStoresOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.029s	user 0.013s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":13509,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.435686  8374 maintenance_manager.cc:419] P b3492c71a3a746d8b8bf69307149fc3b: Scheduling MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a): perf score=1.000000
I20260812 06:16:45.462374  8128 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.003s	sys 0.000s
I20260812 06:16:45.462965  8128 tablet_server.cc:179] TabletServer@127.7.240.1:0 shutting down...
I20260812 06:16:45.561347  8282 maintenance_manager.cc:643] P b3492c71a3a746d8b8bf69307149fc3b: MajorDeltaCompactionOp(c3d08d72cc0f48509df49776805ced6a) complete. Timing: real 0.125s	user 0.085s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":843,"lbm_read_time_us":7916,"lbm_reads_lt_1ms":467,"lbm_write_time_us":20330,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.562021  8128 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:45.562390  8128 tablet_replica.cc:333] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b: stopping tablet replica
I20260812 06:16:45.562602  8128 raft_consensus.cc:2243] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.562839  8128 raft_consensus.cc:2272] T c3d08d72cc0f48509df49776805ced6a P b3492c71a3a746d8b8bf69307149fc3b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.568004  8128 tablet_server.cc:196] TabletServer@127.7.240.1:0 shutdown complete.
I20260812 06:16:45.600006  8128 master.cc:562] Master@127.7.240.62:45499 shutting down...
I20260812 06:16:45.603351  8128 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.603509  8128 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.603587  8128 tablet_replica.cc:333] T 00000000000000000000000000000000 P b10dc34024a84a21b95f12de57357d6f: stopping tablet replica
I20260812 06:16:45.615490  8128 master.cc:584] Master@127.7.240.62:45499 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4960 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:45.687536  8128 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.240.62:43709
I20260812 06:16:45.687911  8128 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:45.689886  8427 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:45.689985  8434 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:16:45.689944  8429 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:45.689970  8128 server_base.cc:1061] running on GCE node
I20260812 06:16:45.690239  8128 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.690280  8128 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:45.690294  8128 hybrid_clock.cc:648] HybridClock initialized: now 1786515405690294 us; error 0 us; skew 500 ppm
I20260812 06:16:45.691042  8128 webserver.cc:533] Webserver started at http://127.7.240.62:42793/ using document root <none> and password file <none>
I20260812 06:16:45.691162  8128 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.691201  8128 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.691256  8128 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.691592  8128 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/master-0-root/instance:
uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-42z9"
I20260812 06:16:45.692889  8128 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.693709  8444 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:45.693907  8128 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.693972  8128 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/master-0-root
uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-42z9"
I20260812 06:16:45.694025  8128 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-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:45.701903  8128 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.702153  8128 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.705736  8128 rpc_server.cc:307] RPC server started. Bound to: 127.7.240.62:43709
I20260812 06:16:45.717730  8523 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:45.717741  8521 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.240.62:43709 every 8 connection(s)
I20260812 06:16:45.719506  8523 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9: Bootstrap starting.
I20260812 06:16:45.720203  8523 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:45.721067  8523 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9: No bootstrap required, opened a new log
I20260812 06:16:45.721419  8523 raft_consensus.cc:359] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9" member_type: VOTER }
I20260812 06:16:45.721531  8523 raft_consensus.cc:385] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:45.721562  8523 raft_consensus.cc:740] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e0c45f3b5f8d44d1a39c58e0effb65b9, State: Initialized, Role: FOLLOWER
I20260812 06:16:45.721676  8523 consensus_queue.cc:260] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [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: "e0c45f3b5f8d44d1a39c58e0effb65b9" member_type: VOTER }
I20260812 06:16:45.721755  8523 raft_consensus.cc:399] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:45.721793  8523 raft_consensus.cc:493] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:45.721823  8523 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:45.722417  8523 raft_consensus.cc:515] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9" member_type: VOTER }
I20260812 06:16:45.722527  8523 leader_election.cc:304] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [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: e0c45f3b5f8d44d1a39c58e0effb65b9; no voters: 
I20260812 06:16:45.722657  8523 leader_election.cc:290] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:45.722765  8529 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:45.722949  8529 raft_consensus.cc:697] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 1 LEADER]: Becoming Leader. State: Replica: e0c45f3b5f8d44d1a39c58e0effb65b9, State: Running, Role: LEADER
I20260812 06:16:45.723078  8529 consensus_queue.cc:237] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [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: "e0c45f3b5f8d44d1a39c58e0effb65b9" member_type: VOTER }
I20260812 06:16:45.723114  8523 sys_catalog.cc:565] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:45.723470  8534 sys_catalog.cc:455] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e0c45f3b5f8d44d1a39c58e0effb65b9. Latest consensus state: current_term: 1 leader_uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9" member_type: VOTER } }
I20260812 06:16:45.723456  8532 sys_catalog.cc:455] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0c45f3b5f8d44d1a39c58e0effb65b9" member_type: VOTER } }
I20260812 06:16:45.723588  8534 sys_catalog.cc:458] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:45.723645  8532 sys_catalog.cc:458] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:45.724123  8538 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:45.724880  8538 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:45.725067  8128 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:45.726663  8538 catalog_manager.cc:1383] Generated new cluster ID: f90739f87c3c4fe5be128144ff4f72f5
I20260812 06:16:45.726722  8538 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:45.732779  8538 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:45.733249  8538 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:45.740185  8538 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9: Generated new TSK 0
I20260812 06:16:45.740314  8538 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:45.741127  8128 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:45.742733  8558 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:45.742877  8557 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:45.742900  8563 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:45.743110  8128 server_base.cc:1061] running on GCE node
I20260812 06:16:45.743252  8128 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.743289  8128 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:45.743302  8128 hybrid_clock.cc:648] HybridClock initialized: now 1786515405743302 us; error 0 us; skew 500 ppm
I20260812 06:16:45.744033  8128 webserver.cc:533] Webserver started at http://127.7.240.1:45285/ using document root <none> and password file <none>
I20260812 06:16:45.744158  8128 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.744194  8128 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.744246  8128 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.744537  8128 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/instance:
uuid: "2d104e86bc1e495cbccbfd339d9cbe32"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-42z9"
I20260812 06:16:45.745879  8128 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:45.746685  8568 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:45.746893  8128 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.746963  8128 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root
uuid: "2d104e86bc1e495cbccbfd339d9cbe32"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-42z9"
I20260812 06:16:45.747025  8128 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-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:45.753888  8128 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.754168  8128 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.754402  8128 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:45.754793  8128 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:45.754830  8128 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.754870  8128 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:45.754899  8128 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.758685  8128 rpc_server.cc:307] RPC server started. Bound to: 127.7.240.1:34465
I20260812 06:16:45.758738  8663 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.240.1:34465 every 8 connection(s)
I20260812 06:16:45.766364  8664 heartbeater.cc:344] Connected to a master server at 127.7.240.62:43709
I20260812 06:16:45.766453  8664 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:45.766646  8664 heartbeater.cc:507] Master 127.7.240.62:43709 requested a full tablet report, sending...
I20260812 06:16:45.767236  8464 ts_manager.cc:194] Registered new tserver with Master: 2d104e86bc1e495cbccbfd339d9cbe32 (127.7.240.1:34465)
I20260812 06:16:45.767794  8128 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008733433s
I20260812 06:16:45.767964  8464 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60234
I20260812 06:16:45.773849  8464 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60246:
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:45.781402  8605 tablet_service.cc:1511] Processing CreateTablet for tablet 487b9dd6fc624c179e0d145b9a591682 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a44ccad6ddf7413cb7f102a7b61a6918]), partition=
I20260812 06:16:45.781672  8605 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 487b9dd6fc624c179e0d145b9a591682. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:45.783408  8682 tablet_bootstrap.cc:492] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Bootstrap starting.
I20260812 06:16:45.784353  8682 tablet_bootstrap.cc:654] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:45.785281  8682 tablet_bootstrap.cc:492] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: No bootstrap required, opened a new log
I20260812 06:16:45.785354  8682 ts_tablet_manager.cc:1403] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:45.785737  8682 raft_consensus.cc:359] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d104e86bc1e495cbccbfd339d9cbe32" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34465 } }
I20260812 06:16:45.785825  8682 raft_consensus.cc:385] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:45.785851  8682 raft_consensus.cc:740] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2d104e86bc1e495cbccbfd339d9cbe32, State: Initialized, Role: FOLLOWER
I20260812 06:16:45.785957  8682 consensus_queue.cc:260] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [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: "2d104e86bc1e495cbccbfd339d9cbe32" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34465 } }
I20260812 06:16:45.786038  8682 raft_consensus.cc:399] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:45.786068  8682 raft_consensus.cc:493] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:45.786104  8682 raft_consensus.cc:3060] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:45.786818  8682 raft_consensus.cc:515] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d104e86bc1e495cbccbfd339d9cbe32" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34465 } }
I20260812 06:16:45.786939  8682 leader_election.cc:304] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [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: 2d104e86bc1e495cbccbfd339d9cbe32; no voters: 
I20260812 06:16:45.787135  8682 leader_election.cc:290] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:45.787230  8684 raft_consensus.cc:2804] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:45.787424  8684 raft_consensus.cc:697] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 1 LEADER]: Becoming Leader. State: Replica: 2d104e86bc1e495cbccbfd339d9cbe32, State: Running, Role: LEADER
I20260812 06:16:45.787475  8682 ts_tablet_manager.cc:1434] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:45.787627  8664 heartbeater.cc:499] Master 127.7.240.62:43709 was elected leader, sending a full tablet report...
I20260812 06:16:45.787701  8684 consensus_queue.cc:237] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [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: "2d104e86bc1e495cbccbfd339d9cbe32" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34465 } }
I20260812 06:16:45.788947  8464 catalog_manager.cc:5719] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2d104e86bc1e495cbccbfd339d9cbe32 (127.7.240.1). New cstate: current_term: 1 leader_uuid: "2d104e86bc1e495cbccbfd339d9cbe32" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d104e86bc1e495cbccbfd339d9cbe32" member_type: VOTER last_known_addr { host: "127.7.240.1" port: 34465 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:45.840850  8128 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.012s	sys 0.009s
I20260812 06:16:46.009677  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushMRSOp(487b9dd6fc624c179e0d145b9a591682): perf score=23.023690
I20260812 06:16:46.167369  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushMRSOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.157s	user 0.111s	sys 0.044s Metrics: {"bytes_written":13497196,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":760,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39822,"lbm_writes_lt_1ms":886,"mutex_wait_us":170,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1645}
I20260812 06:16:46.168057  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling LogGCOp(487b9dd6fc624c179e0d145b9a591682): free 20743880 bytes of WAL
I20260812 06:16:46.168283  8573 log_reader.cc:385] T 487b9dd6fc624c179e0d145b9a591682: removed 2 log segments from log reader
I20260812 06:16:46.168347  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000001 (ops 1-6)
I20260812 06:16:46.168406  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000002 (ops 7-11)
I20260812 06:16:46.173259  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: LogGCOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:46.173625  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682): 20513814 bytes on disk
I20260812 06:16:46.174130  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.174503  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=3.181125
I20260812 06:16:46.189687  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":5169290,"delete_count":0,"lbm_write_time_us":6114,"lbm_writes_lt_1ms":129,"reinsert_count":0,"update_count":630}
I20260812 06:16:46.190109  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:46.197857  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":2553,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:16:46.198254  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:46.375097  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.177s	user 0.120s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815759,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":663,"lbm_read_time_us":12489,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26225,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":320,"threads_started":5,"update_count":2500}
I20260812 06:16:46.375628  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:46.431075  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.055s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18129,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.431648  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:46.441434  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.441920  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:46.611284  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.169s	user 0.128s	sys 0.040s 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":537,"lbm_read_time_us":11919,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25840,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:16:46.611819  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=11.118625
I20260812 06:16:46.659219  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.047s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12008,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1550}
I20260812 06:16:46.659789  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:46.669938  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.670364  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:46.678660  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3042,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.679116  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:46.847875  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.169s	user 0.116s	sys 0.045s 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":175,"lbm_read_time_us":9058,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26025,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:16:46.848344  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:46.894637  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.046s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19032,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.895254  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:46.914631  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.915092  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:47.063256  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.148s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":11229,"lbm_reads_lt_1ms":568,"lbm_write_time_us":24133,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:16:47.063776  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=10.126437
I20260812 06:16:47.100425  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.036s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14846,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.101073  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:47.224995  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":95,"lbm_read_time_us":7380,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22821,"lbm_writes_lt_1ms":343,"mutex_wait_us":36,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":58368,"update_count":1500}
I20260812 06:16:47.225620  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=10.126437
I20260812 06:16:47.258563  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.033s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13440,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.259073  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:47.363284  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.104s	user 0.092s	sys 0.012s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":119,"lbm_read_time_us":5674,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18214,"lbm_writes_lt_1ms":343,"mutex_wait_us":20,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":1500}
I20260812 06:16:47.363827  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=10.126437
I20260812 06:16:47.404036  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.040s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12875,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.404594  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:47.414191  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.414666  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushMRSOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:47.442631  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushMRSOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.028s	user 0.024s	sys 0.002s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1343,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1423,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":1664}
I20260812 06:16:47.443202  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling LogGCOp(487b9dd6fc624c179e0d145b9a591682): free 121006440 bytes of WAL
I20260812 06:16:47.443423  8573 log_reader.cc:385] T 487b9dd6fc624c179e0d145b9a591682: removed 12 log segments from log reader
I20260812 06:16:47.443470  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000003 (ops 12-16)
I20260812 06:16:47.443497  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000004 (ops 17-21)
I20260812 06:16:47.443531  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000005 (ops 22-26)
I20260812 06:16:47.443562  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000006 (ops 27-31)
I20260812 06:16:47.443594  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000007 (ops 32-36)
I20260812 06:16:47.443627  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000008 (ops 37-41)
I20260812 06:16:47.443658  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000009 (ops 42-46)
I20260812 06:16:47.443691  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000010 (ops 47-50)
I20260812 06:16:47.443722  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000011 (ops 51-55)
I20260812 06:16:47.443751  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000012 (ops 56-60)
I20260812 06:16:47.443782  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000013 (ops 61-65)
I20260812 06:16:47.443812  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000014 (ops 66-70)
I20260812 06:16:47.464746  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: LogGCOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:16:47.465142  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682): 472 bytes on disk
I20260812 06:16:47.465610  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.466069  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=3.181125
I20260812 06:16:47.484651  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.018s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:47.485033  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:47.498385  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5035,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.498773  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:47.692862  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.194s	user 0.146s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":263,"lbm_read_time_us":14012,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31863,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20352,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:16:47.693588  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:47.745388  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.052s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18224,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.745913  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:47.756043  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.756436  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:47.931752  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.175s	user 0.113s	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":132,"lbm_read_time_us":11204,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27159,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:16:47.932271  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:47.991809  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.059s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18081,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.992386  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.002664  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.003127  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:48.168869  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.166s	user 0.118s	sys 0.048s 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":97,"lbm_read_time_us":10931,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28102,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:48.169503  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=11.118625
I20260812 06:16:48.196924  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.027s	user 0.012s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11022,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:48.197840  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.223760  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.026s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.224273  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.234135  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3732,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.234694  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:48.396801  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.162s	user 0.110s	sys 0.048s 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":824,"lbm_read_time_us":8764,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25591,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:48.397364  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:48.451148  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.054s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23653,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.451663  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.462673  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.463086  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:48.611045  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.148s	user 0.104s	sys 0.032s 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":758,"lbm_read_time_us":9267,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25178,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:48.613811  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:48.659476  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19864,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.659983  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.670249  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.671113  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:48.808073  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.137s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":953,"lbm_read_time_us":8964,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25335,"lbm_writes_lt_1ms":543,"mutex_wait_us":248,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:48.808676  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=11.118625
I20260812 06:16:48.844038  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.035s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14780,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:48.844686  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.856426  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3917,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.856941  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushMRSOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:48.909804  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushMRSOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.053s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":1146,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1505,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:48.910565  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling LogGCOp(487b9dd6fc624c179e0d145b9a591682): free 136275199 bytes of WAL
I20260812 06:16:48.910804  8573 log_reader.cc:385] T 487b9dd6fc624c179e0d145b9a591682: removed 13 log segments from log reader
I20260812 06:16:48.910852  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000015 (ops 71-75)
I20260812 06:16:48.910897  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000016 (ops 76-80)
I20260812 06:16:48.910933  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000017 (ops 81-85)
I20260812 06:16:48.910964  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000018 (ops 86-90)
I20260812 06:16:48.910996  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000019 (ops 91-95)
I20260812 06:16:48.911027  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000020 (ops 96-100)
I20260812 06:16:48.911058  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000021 (ops 101-105)
I20260812 06:16:48.911088  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000022 (ops 106-110)
I20260812 06:16:48.911118  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000023 (ops 111-115)
I20260812 06:16:48.911149  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000024 (ops 116-120)
I20260812 06:16:48.911180  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000025 (ops 121-125)
I20260812 06:16:48.911211  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000026 (ops 126-130)
I20260812 06:16:48.911240  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000027 (ops 131-134)
I20260812 06:16:48.934237  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: LogGCOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:48.934698  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=7.149875
I20260812 06:16:48.956704  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.022s	user 0.019s	sys 0.000s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":9017,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:48.957144  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682): 493 bytes on disk
I20260812 06:16:48.957617  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682) 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:16:48.958098  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:48.979523  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5485,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.980034  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:49.200604  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.220s	user 0.147s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020731,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3007,"lbm_read_time_us":15143,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36822,"lbm_writes_lt_1ms":743,"mutex_wait_us":2226,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:16:49.201169  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=18.063937
I20260812 06:16:49.252020  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.051s	user 0.027s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":21167,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:49.252550  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:49.263516  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.263976  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:49.452934  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.189s	user 0.108s	sys 0.078s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":12297,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29007,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3000}
I20260812 06:16:49.456980  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=16.079562
I20260812 06:16:49.504287  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.047s	user 0.017s	sys 0.020s Metrics: {"bytes_written":17558580,"delete_count":0,"lbm_write_time_us":17146,"lbm_writes_lt_1ms":431,"reinsert_count":0,"update_count":2140}
I20260812 06:16:49.504786  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:49.515830  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.011s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3364209,"delete_count":0,"lbm_write_time_us":2938,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:16:49.516278  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:49.528990  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.529453  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:49.711016  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.181s	user 0.120s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918189,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":217,"lbm_read_time_us":12442,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29021,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:16:49.711510  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=15.087375
I20260812 06:16:49.757519  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":19577,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:49.758116  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:49.779213  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.021s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.779687  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:49.793838  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.794303  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:49.977223  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.183s	user 0.114s	sys 0.065s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":348,"lbm_read_time_us":12419,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31223,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:16:49.977839  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=15.087375
I20260812 06:16:50.018707  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.041s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":18053,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:50.019241  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:50.030332  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.030778  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:50.201362  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.170s	user 0.104s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815669,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":10970,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27438,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:16:50.201969  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=14.095187
I20260812 06:16:50.253363  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.051s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18395,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.253919  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:50.263958  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.264513  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushMRSOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:50.296005  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushMRSOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.031s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1306,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1401,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:50.296818  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling LogGCOp(487b9dd6fc624c179e0d145b9a591682): free 121006700 bytes of WAL
I20260812 06:16:50.297086  8573 log_reader.cc:385] T 487b9dd6fc624c179e0d145b9a591682: removed 12 log segments from log reader
I20260812 06:16:50.297135  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000028 (ops 135-139)
I20260812 06:16:50.297174  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000029 (ops 140-144)
I20260812 06:16:50.297207  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000030 (ops 145-149)
I20260812 06:16:50.297238  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000031 (ops 150-154)
I20260812 06:16:50.297271  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000032 (ops 155-158)
I20260812 06:16:50.297302  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000033 (ops 159-163)
I20260812 06:16:50.297333  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000034 (ops 164-168)
I20260812 06:16:50.297364  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000035 (ops 169-173)
I20260812 06:16:50.297394  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000036 (ops 174-178)
I20260812 06:16:50.297425  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000037 (ops 179-183)
I20260812 06:16:50.297490  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000038 (ops 184-188)
I20260812 06:16:50.297523  8573 log.cc:1079] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: Deleting log segment in path: /tmp/dist-test-task8gbDMG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400717117-8128-0/minicluster-data/ts-0-root/wals/487b9dd6fc624c179e0d145b9a591682/wal-000000039 (ops 189-193)
I20260812 06:16:50.317845  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: LogGCOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.021s	user 0.007s	sys 0.014s Metrics: {}
I20260812 06:16:50.318279  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:50.338213  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.020s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.338640  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682): perf score=2.188937
I20260812 06:16:50.348652  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: FlushDeltaMemStoresOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.349053  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682): 472 bytes on disk
I20260812 06:16:50.349426  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: UndoDeltaBlockGCOp(487b9dd6fc624c179e0d145b9a591682) 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:50.349946  8665 maintenance_manager.cc:419] P 2d104e86bc1e495cbccbfd339d9cbe32: Scheduling MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682): perf score=1.000000
I20260812 06:16:50.384546  8128 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.544s	user 1.706s	sys 0.118s
I20260812 06:16:50.462493  8128 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.003s	sys 0.000s
I20260812 06:16:50.463075  8128 tablet_server.cc:179] TabletServer@127.7.240.1:0 shutting down...
I20260812 06:16:50.539726  8573 maintenance_manager.cc:643] P 2d104e86bc1e495cbccbfd339d9cbe32: MajorDeltaCompactionOp(487b9dd6fc624c179e0d145b9a591682) complete. Timing: real 0.190s	user 0.098s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020748,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3490,"dirs.run_cpu_time_us":854,"dirs.run_wall_time_us":8099,"lbm_read_time_us":15234,"lbm_reads_lt_1ms":770,"lbm_write_time_us":29795,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":3500}
I20260812 06:16:50.542168  8128 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:50.542527  8128 tablet_replica.cc:333] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32: stopping tablet replica
I20260812 06:16:50.542676  8128 raft_consensus.cc:2243] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.542840  8128 raft_consensus.cc:2272] T 487b9dd6fc624c179e0d145b9a591682 P 2d104e86bc1e495cbccbfd339d9cbe32 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.559788  8128 tablet_server.cc:196] TabletServer@127.7.240.1:0 shutdown complete.
I20260812 06:16:50.591032  8128 master.cc:562] Master@127.7.240.62:43709 shutting down...
I20260812 06:16:50.594516  8128 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.594676  8128 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.594744  8128 tablet_replica.cc:333] T 00000000000000000000000000000000 P e0c45f3b5f8d44d1a39c58e0effb65b9: stopping tablet replica
I20260812 06:16:50.607806  8128 master.cc:584] Master@127.7.240.62:43709 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4991 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9953 ms total)

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