[==========] 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:18:41.325244  5659 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.134.254:35707
I20260812 06:18:41.326280  5659 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:18:41.326905  5659 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:41.333336  5659 server_base.cc:1061] running on GCE node
W20260812 06:18:41.333375  5667 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:18:41.333465  5671 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:18:41.333653  5666 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.334131  5659 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.334255  5659 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:18:41.334319  5659 hybrid_clock.cc:648] HybridClock initialized: now 1786515521334316 us; error 0 us; skew 500 ppm
I20260812 06:18:41.336088  5659 webserver.cc:533] Webserver started at http://127.5.134.254:45009/ using document root <none> and password file <none>
I20260812 06:18:41.336617  5659 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.336720  5659 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.336968  5659 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.338589  5659 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/master-0-root/instance:
uuid: "d2b21b5fd45d4580bf6ee01ee5e12267"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-s11t"
I20260812 06:18:41.342005  5659 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:18:41.343992  5681 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:18:41.345039  5659 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:41.345187  5659 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/master-0-root
uuid: "d2b21b5fd45d4580bf6ee01ee5e12267"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-s11t"
I20260812 06:18:41.345294  5659 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-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:18:41.362830  5659 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.363458  5659 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:18:41.363646  5659 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.372315  5659 rpc_server.cc:307] RPC server started. Bound to: 127.5.134.254:35707
I20260812 06:18:41.372345  5766 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.134.254:35707 every 8 connection(s)
I20260812 06:18:41.374598  5767 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:18:41.379884  5767 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: Bootstrap starting.
I20260812 06:18:41.382251  5767 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.383149  5767 log.cc:826] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:41.384805  5767 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: No bootstrap required, opened a new log
I20260812 06:18:41.387446  5767 raft_consensus.cc:359] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b21b5fd45d4580bf6ee01ee5e12267" member_type: VOTER }
I20260812 06:18:41.387601  5767 raft_consensus.cc:385] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.387727  5767 raft_consensus.cc:740] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2b21b5fd45d4580bf6ee01ee5e12267, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.388314  5767 consensus_queue.cc:260] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [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: "d2b21b5fd45d4580bf6ee01ee5e12267" member_type: VOTER }
I20260812 06:18:41.388485  5767 raft_consensus.cc:399] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.388578  5767 raft_consensus.cc:493] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.388751  5767 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.389528  5767 raft_consensus.cc:515] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b21b5fd45d4580bf6ee01ee5e12267" member_type: VOTER }
I20260812 06:18:41.389955  5767 leader_election.cc:304] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [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: d2b21b5fd45d4580bf6ee01ee5e12267; no voters: 
I20260812 06:18:41.390333  5767 leader_election.cc:290] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.390451  5773 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.390710  5773 raft_consensus.cc:697] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 1 LEADER]: Becoming Leader. State: Replica: d2b21b5fd45d4580bf6ee01ee5e12267, State: Running, Role: LEADER
I20260812 06:18:41.391134  5773 consensus_queue.cc:237] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [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: "d2b21b5fd45d4580bf6ee01ee5e12267" member_type: VOTER }
I20260812 06:18:41.391306  5767 sys_catalog.cc:565] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:41.393177  5775 sys_catalog.cc:455] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d2b21b5fd45d4580bf6ee01ee5e12267. Latest consensus state: current_term: 1 leader_uuid: "d2b21b5fd45d4580bf6ee01ee5e12267" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b21b5fd45d4580bf6ee01ee5e12267" member_type: VOTER } }
I20260812 06:18:41.393306  5775 sys_catalog.cc:458] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.393158  5774 sys_catalog.cc:455] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d2b21b5fd45d4580bf6ee01ee5e12267" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b21b5fd45d4580bf6ee01ee5e12267" member_type: VOTER } }
I20260812 06:18:41.393577  5774 sys_catalog.cc:458] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.393682  5659 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:41.395709  5797 catalog_manager.cc:1594] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:41.395799  5797 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:41.395861  5796 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:41.396579  5796 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:41.401053  5796 catalog_manager.cc:1383] Generated new cluster ID: ca68961d1a824a8bb191d2fb5932ac4b
I20260812 06:18:41.401122  5796 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:41.419157  5796 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:41.420034  5796 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:41.433986  5796 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: Generated new TSK 0
I20260812 06:18:41.434667  5796 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:41.458786  5659 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.461900  5804 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:18:41.461987  5806 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:18:41.462080  5659 server_base.cc:1061] running on GCE node
W20260812 06:18:41.461983  5808 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:18:41.462455  5659 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.462514  5659 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:18:41.462538  5659 hybrid_clock.cc:648] HybridClock initialized: now 1786515521462538 us; error 0 us; skew 500 ppm
I20260812 06:18:41.463500  5659 webserver.cc:533] Webserver started at http://127.5.134.193:33799/ using document root <none> and password file <none>
I20260812 06:18:41.463666  5659 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.463724  5659 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.463802  5659 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.464239  5659 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/instance:
uuid: "8c76ee879dde4d21a25e0fa7c8e51d4c"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-s11t"
I20260812 06:18:41.466233  5659 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:41.467324  5814 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:18:41.467584  5659 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:41.467656  5659 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root
uuid: "8c76ee879dde4d21a25e0fa7c8e51d4c"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-s11t"
I20260812 06:18:41.467746  5659 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-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:18:41.478523  5659 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.478989  5659 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.479524  5659 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:41.480357  5659 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:41.480417  5659 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.480492  5659 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:41.480532  5659 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.487833  5659 rpc_server.cc:307] RPC server started. Bound to: 127.5.134.193:35303
I20260812 06:18:41.487876  5920 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.134.193:35303 every 8 connection(s)
I20260812 06:18:41.498665  5921 heartbeater.cc:344] Connected to a master server at 127.5.134.254:35707
I20260812 06:18:41.498941  5921 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:41.499387  5921 heartbeater.cc:507] Master 127.5.134.254:35707 requested a full tablet report, sending...
I20260812 06:18:41.500949  5701 ts_manager.cc:194] Registered new tserver with Master: 8c76ee879dde4d21a25e0fa7c8e51d4c (127.5.134.193:35303)
I20260812 06:18:41.501057  5659 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012563803s
I20260812 06:18:41.502455  5701 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56352
I20260812 06:18:41.510744  5701 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56358:
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:18:41.524520  5866 tablet_service.cc:1511] Processing CreateTablet for tablet ff14ece5b13b47cbb071b60ff56d9d6f (DEFAULT_TABLE table=heavy-update-compaction-test [id=ad44c9c9163f44f98cea3c287fb81290]), partition=
I20260812 06:18:41.525039  5866 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ff14ece5b13b47cbb071b60ff56d9d6f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:41.527243  5947 tablet_bootstrap.cc:492] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Bootstrap starting.
I20260812 06:18:41.528743  5947 tablet_bootstrap.cc:654] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.529884  5947 tablet_bootstrap.cc:492] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: No bootstrap required, opened a new log
I20260812 06:18:41.530005  5947 ts_tablet_manager.cc:1403] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:41.530529  5947 raft_consensus.cc:359] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c76ee879dde4d21a25e0fa7c8e51d4c" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 35303 } }
I20260812 06:18:41.530651  5947 raft_consensus.cc:385] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.530684  5947 raft_consensus.cc:740] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c76ee879dde4d21a25e0fa7c8e51d4c, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.530829  5947 consensus_queue.cc:260] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [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: "8c76ee879dde4d21a25e0fa7c8e51d4c" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 35303 } }
I20260812 06:18:41.530941  5947 raft_consensus.cc:399] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.530992  5947 raft_consensus.cc:493] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.531046  5947 raft_consensus.cc:3060] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.532310  5947 raft_consensus.cc:515] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c76ee879dde4d21a25e0fa7c8e51d4c" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 35303 } }
I20260812 06:18:41.532469  5947 leader_election.cc:304] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [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: 8c76ee879dde4d21a25e0fa7c8e51d4c; no voters: 
I20260812 06:18:41.532722  5947 leader_election.cc:290] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.532833  5951 raft_consensus.cc:2804] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.533121  5947 ts_tablet_manager.cc:1434] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:41.533154  5951 raft_consensus.cc:697] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 1 LEADER]: Becoming Leader. State: Replica: 8c76ee879dde4d21a25e0fa7c8e51d4c, State: Running, Role: LEADER
I20260812 06:18:41.533331  5921 heartbeater.cc:499] Master 127.5.134.254:35707 was elected leader, sending a full tablet report...
I20260812 06:18:41.533442  5951 consensus_queue.cc:237] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [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: "8c76ee879dde4d21a25e0fa7c8e51d4c" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 35303 } }
I20260812 06:18:41.536271  5701 catalog_manager.cc:5719] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c reported cstate change: term changed from 0 to 1, leader changed from <none> to 8c76ee879dde4d21a25e0fa7c8e51d4c (127.5.134.193). New cstate: current_term: 1 leader_uuid: "8c76ee879dde4d21a25e0fa7c8e51d4c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c76ee879dde4d21a25e0fa7c8e51d4c" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 35303 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:41.603132  5659 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.013s	sys 0.014s
I20260812 06:18:41.738984  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=19.054940
I20260812 06:18:41.920189  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.181s	user 0.140s	sys 0.032s Metrics: {"bytes_written":12307493,"cfile_init":1,"compiler_manager_pool.queue_time_us":205,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":808,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41360,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":131,"threads_started":1,"update_count":1500}
I20260812 06:18:41.921353  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): free 20743831 bytes of WAL
I20260812 06:18:41.921679  5829 log_reader.cc:385] T ff14ece5b13b47cbb071b60ff56d9d6f: removed 2 log segments from log reader
I20260812 06:18:41.921758  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000001 (ops 1-6)
I20260812 06:18:41.921813  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000002 (ops 7-11)
I20260812 06:18:41.927402  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:41.927711  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): 16411397 bytes on disk
I20260812 06:18:41.928336  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.928768  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:41.946501  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.947114  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:42.099382  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.152s	user 0.129s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":579,"lbm_read_time_us":8460,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27085,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":308,"threads_started":5,"update_count":2000}
I20260812 06:18:42.099897  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:42.144872  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.045s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18041,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.145382  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:42.157920  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4545,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.158509  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:42.300158  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.141s	user 0.121s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":8273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27747,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:18:42.300930  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:42.343515  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.042s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14625,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.343953  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:42.354274  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.354712  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:42.483207  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":10585,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24314,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:18:42.483773  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:42.535192  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.051s	user 0.032s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16322,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.535733  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:42.547914  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.548427  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:42.704146  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.156s	user 0.119s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":11857,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26350,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:18:42.704914  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:42.741907  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.037s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15536,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.742483  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:42.753916  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.754424  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:42.879245  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.125s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":9068,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24556,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:42.879784  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:42.912563  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.033s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12348516,"delete_count":0,"lbm_write_time_us":14297,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1505}
I20260812 06:18:42.913100  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:42.929198  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6414,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:42.929687  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:43.050930  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.121s	user 0.106s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":66,"lbm_read_time_us":7801,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24504,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:18:43.051714  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:43.089857  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.038s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14474,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.090377  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:43.101174  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.101603  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:43.129688  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.028s	user 0.024s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":320,"dirs.run_wall_time_us":1576,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1546,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:43.130601  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): free 112692420 bytes of WAL
I20260812 06:18:43.130854  5829 log_reader.cc:385] T ff14ece5b13b47cbb071b60ff56d9d6f: removed 11 log segments from log reader
I20260812 06:18:43.130923  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000003 (ops 12-16)
I20260812 06:18:43.130975  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000004 (ops 17-21)
I20260812 06:18:43.131033  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000005 (ops 22-26)
I20260812 06:18:43.131076  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000006 (ops 27-31)
I20260812 06:18:43.131117  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000007 (ops 32-36)
I20260812 06:18:43.131158  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000008 (ops 37-41)
I20260812 06:18:43.131197  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000009 (ops 42-46)
I20260812 06:18:43.131237  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000010 (ops 47-51)
I20260812 06:18:43.131278  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000011 (ops 52-56)
I20260812 06:18:43.131317  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000012 (ops 57-61)
I20260812 06:18:43.131345  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000013 (ops 62-66)
I20260812 06:18:43.157455  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:43.157925  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=3.181125
I20260812 06:18:43.170733  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.171166  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:43.184265  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5114,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.184770  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:43.376356  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.191s	user 0.129s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":901,"lbm_read_time_us":14371,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37582,"lbm_writes_lt_1ms":643,"mutex_wait_us":340,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:43.377034  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): 448 bytes on disk
I20260812 06:18:43.377568  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.378255  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:43.428813  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.050s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19457,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.429263  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:43.440462  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.440973  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:43.602155  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.161s	user 0.128s	sys 0.017s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":473,"lbm_read_time_us":9610,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31283,"lbm_writes_lt_1ms":543,"mutex_wait_us":164,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:18:43.602734  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:43.664018  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.061s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26771,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.664510  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:43.675047  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.675549  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:43.849125  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.173s	user 0.117s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":13389,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27902,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:43.849802  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:43.899268  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.049s	user 0.027s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22090,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.899783  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:44.056164  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.156s	user 0.094s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":996,"lbm_read_time_us":9258,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26874,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":119424,"update_count":2000}
I20260812 06:18:44.056998  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:44.109508  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.052s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21012,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.110055  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:44.121696  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.122169  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:44.306674  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.184s	user 0.103s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":10009,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29619,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:18:44.307329  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:44.357463  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21150,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.357928  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:44.368865  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.369530  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:44.527876  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.158s	user 0.119s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":12672,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31506,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25984,"update_count":2500}
I20260812 06:18:44.528604  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:44.567724  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.039s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16819,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.568334  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:44.579159  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.580004  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:44.613761  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.034s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1252,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2026,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:44.614665  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): free 120553380 bytes of WAL
I20260812 06:18:44.614951  5829 log_reader.cc:385] T ff14ece5b13b47cbb071b60ff56d9d6f: removed 12 log segments from log reader
I20260812 06:18:44.615025  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000014 (ops 67-71)
I20260812 06:18:44.615080  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000015 (ops 72-76)
I20260812 06:18:44.615139  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000016 (ops 77-80)
I20260812 06:18:44.615180  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000017 (ops 81-85)
I20260812 06:18:44.615219  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000018 (ops 86-90)
I20260812 06:18:44.615257  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000019 (ops 91-95)
I20260812 06:18:44.615294  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000020 (ops 96-100)
I20260812 06:18:44.615346  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000021 (ops 101-104)
I20260812 06:18:44.615449  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000022 (ops 105-109)
I20260812 06:18:44.615492  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000023 (ops 110-114)
I20260812 06:18:44.615530  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000024 (ops 115-119)
I20260812 06:18:44.615566  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000025 (ops 120-124)
I20260812 06:18:44.644372  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:44.644860  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=3.181125
I20260812 06:18:44.663911  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7492,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.664448  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): free 11564877 bytes of WAL
I20260812 06:18:44.664728  5829 log_reader.cc:385] T ff14ece5b13b47cbb071b60ff56d9d6f: removed 1 log segments from log reader
I20260812 06:18:44.664800  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000026 (ops 125-128)
I20260812 06:18:44.667047  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:44.667434  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): 472 bytes on disk
I20260812 06:18:44.667861  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.668332  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:44.678226  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3707,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.678845  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:44.886040  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.207s	user 0.143s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1379,"lbm_read_time_us":13648,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33420,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":191,"threads_started":1,"update_count":3000}
I20260812 06:18:44.886885  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:44.943149  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.056s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:44.943629  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:44.954993  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.955516  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:45.149147  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.193s	user 0.131s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":12091,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30012,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:45.149739  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:45.202718  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.053s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21237,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.203263  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:45.214586  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4326,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.215231  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:45.374651  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.159s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":348,"lbm_read_time_us":12185,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28704,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:45.375311  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:45.409991  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.034s	user 0.017s	sys 0.016s 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:18:45.410633  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:45.429531  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.430086  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:45.558422  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.128s	user 0.105s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":585,"lbm_read_time_us":8717,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23388,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:45.559015  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=11.118625
I20260812 06:18:45.603665  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.044s	user 0.031s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18843,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.604212  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:45.614274  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.615023  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:45.745039  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.130s	user 0.103s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":8734,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24932,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:45.745738  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:45.796597  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.051s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18878,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.797351  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:45.814949  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.815600  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:45.993357  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.177s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":13886,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29164,"lbm_writes_lt_1ms":443,"mutex_wait_us":10,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.994134  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:46.032970  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.033601  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:46.049849  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.016s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.050443  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:46.081745  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushMRSOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1217,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2049,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:46.082661  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): free 112239552 bytes of WAL
I20260812 06:18:46.082978  5829 log_reader.cc:385] T ff14ece5b13b47cbb071b60ff56d9d6f: removed 11 log segments from log reader
I20260812 06:18:46.083078  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000027 (ops 129-133)
I20260812 06:18:46.083133  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000028 (ops 134-138)
I20260812 06:18:46.083179  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000029 (ops 139-142)
I20260812 06:18:46.083211  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000030 (ops 143-147)
I20260812 06:18:46.083247  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000031 (ops 148-152)
I20260812 06:18:46.083298  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000032 (ops 153-157)
I20260812 06:18:46.083329  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000033 (ops 158-162)
I20260812 06:18:46.083355  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000034 (ops 163-167)
I20260812 06:18:46.083392  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000035 (ops 168-172)
I20260812 06:18:46.083429  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000036 (ops 173-177)
I20260812 06:18:46.083468  5829 log.cc:1079] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/ff14ece5b13b47cbb071b60ff56d9d6f/wal-000000037 (ops 178-182)
I20260812 06:18:46.112434  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: LogGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.030s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:18:46.112944  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=3.181125
I20260812 06:18:46.130515  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.017s	user 0.004s	sys 0.012s Metrics: {"bytes_written":5005192,"delete_count":0,"lbm_write_time_us":7511,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:18:46.131050  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:46.149993  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3188,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:46.150719  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f): 463 bytes on disk
I20260812 06:18:46.151372  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: UndoDeltaBlockGCOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.152297  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:46.357095  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.205s	user 0.126s	sys 0.077s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877318,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1854,"lbm_read_time_us":14283,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39476,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:46.357820  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=14.095187
I20260812 06:18:46.418792  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.061s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.419415  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=2.188937
I20260812 06:18:46.430150  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.430605  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:46.583076  5659 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.980s	user 1.850s	sys 0.125s
I20260812 06:18:46.602815  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.172s	user 0.127s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":13033,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29019,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:46.603325  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=10.126437
I20260812 06:18:46.628424  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: FlushDeltaMemStoresOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.025s	user 0.016s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11831,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.628960  5923 maintenance_manager.cc:419] P 8c76ee879dde4d21a25e0fa7c8e51d4c: Scheduling MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f): perf score=1.000000
I20260812 06:18:46.646224  5659 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.062s	user 0.002s	sys 0.000s
I20260812 06:18:46.646919  5659 tablet_server.cc:179] TabletServer@127.5.134.193:0 shutting down...
I20260812 06:18:46.727201  5829 maintenance_manager.cc:643] P 8c76ee879dde4d21a25e0fa7c8e51d4c: MajorDeltaCompactionOp(ff14ece5b13b47cbb071b60ff56d9d6f) complete. Timing: real 0.098s	user 0.069s	sys 0.029s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":469,"lbm_read_time_us":6396,"lbm_reads_lt_1ms":367,"lbm_write_time_us":21061,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":75,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.727985  5659 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:46.728422  5659 tablet_replica.cc:333] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c: stopping tablet replica
I20260812 06:18:46.728711  5659 raft_consensus.cc:2243] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.729094  5659 raft_consensus.cc:2272] T ff14ece5b13b47cbb071b60ff56d9d6f P 8c76ee879dde4d21a25e0fa7c8e51d4c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.745582  5659 tablet_server.cc:196] TabletServer@127.5.134.193:0 shutdown complete.
I20260812 06:18:46.759485  5659 master.cc:562] Master@127.5.134.254:35707 shutting down...
I20260812 06:18:46.763780  5659 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.763957  5659 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.764056  5659 tablet_replica.cc:333] T 00000000000000000000000000000000 P d2b21b5fd45d4580bf6ee01ee5e12267: stopping tablet replica
I20260812 06:18:46.776875  5659 master.cc:584] Master@127.5.134.254:35707 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5549 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:46.874192  5659 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.134.254:43977
I20260812 06:18:46.874626  5659 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.876798  5975 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:18:46.876928  5980 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:18:46.876837  5977 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:18:46.876875  5659 server_base.cc:1061] running on GCE node
I20260812 06:18:46.877256  5659 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.877301  5659 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:18:46.877317  5659 hybrid_clock.cc:648] HybridClock initialized: now 1786515526877317 us; error 0 us; skew 500 ppm
I20260812 06:18:46.878198  5659 webserver.cc:533] Webserver started at http://127.5.134.254:45223/ using document root <none> and password file <none>
I20260812 06:18:46.878381  5659 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.878450  5659 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.878530  5659 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.878942  5659 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/master-0-root/instance:
uuid: "5dba0fa059994effb9c54dded3792325"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-s11t"
I20260812 06:18:46.880468  5659 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:46.881564  5986 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:18:46.881834  5659 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:46.881937  5659 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/master-0-root
uuid: "5dba0fa059994effb9c54dded3792325"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-s11t"
I20260812 06:18:46.882030  5659 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-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:18:46.905983  5659 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.906450  5659 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.910885  5659 rpc_server.cc:307] RPC server started. Bound to: 127.5.134.254:43977
I20260812 06:18:46.925709  6073 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.134.254:43977 every 8 connection(s)
I20260812 06:18:46.926052  6076 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:18:46.928059  6076 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325: Bootstrap starting.
I20260812 06:18:46.928958  6076 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.930023  6076 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325: No bootstrap required, opened a new log
I20260812 06:18:46.930466  6076 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5dba0fa059994effb9c54dded3792325" member_type: VOTER }
I20260812 06:18:46.930583  6076 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.930644  6076 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5dba0fa059994effb9c54dded3792325, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.930806  6076 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [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: "5dba0fa059994effb9c54dded3792325" member_type: VOTER }
I20260812 06:18:46.930902  6076 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.930948  6076 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.931003  6076 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.931697  6076 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5dba0fa059994effb9c54dded3792325" member_type: VOTER }
I20260812 06:18:46.931854  6076 leader_election.cc:304] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [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: 5dba0fa059994effb9c54dded3792325; no voters: 
I20260812 06:18:46.932065  6076 leader_election.cc:290] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.932219  6083 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.932476  6083 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 1 LEADER]: Becoming Leader. State: Replica: 5dba0fa059994effb9c54dded3792325, State: Running, Role: LEADER
I20260812 06:18:46.932567  6076 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:46.932651  6083 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [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: "5dba0fa059994effb9c54dded3792325" member_type: VOTER }
I20260812 06:18:46.933178  6085 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5dba0fa059994effb9c54dded3792325. Latest consensus state: current_term: 1 leader_uuid: "5dba0fa059994effb9c54dded3792325" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5dba0fa059994effb9c54dded3792325" member_type: VOTER } }
I20260812 06:18:46.933292  6085 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.933166  6084 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5dba0fa059994effb9c54dded3792325" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5dba0fa059994effb9c54dded3792325" member_type: VOTER } }
I20260812 06:18:46.933367  6084 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.933984  6092 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:46.934666  6092 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:46.934927  5659 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:46.936618  6092 catalog_manager.cc:1383] Generated new cluster ID: 4dad9384a80b40bc8aaf6b0234ee23c1
I20260812 06:18:46.936717  6092 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:46.956458  6092 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:46.957134  6092 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:46.964342  6092 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325: Generated new TSK 0
I20260812 06:18:46.964550  6092 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:46.967448  5659 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.969589  6110 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:18:46.969630  6114 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:18:46.969599  6109 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:46.969964  5659 server_base.cc:1061] running on GCE node
I20260812 06:18:46.970115  5659 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.970149  5659 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:18:46.970165  5659 hybrid_clock.cc:648] HybridClock initialized: now 1786515526970165 us; error 0 us; skew 500 ppm
I20260812 06:18:46.970958  5659 webserver.cc:533] Webserver started at http://127.5.134.193:44797/ using document root <none> and password file <none>
I20260812 06:18:46.971103  5659 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.971153  5659 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.971204  5659 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.971638  5659 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/instance:
uuid: "f016cf66408a49599389c20fc4969e4b"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-s11t"
I20260812 06:18:46.973276  5659 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:46.974274  6121 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:18:46.974601  5659 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:46.974668  5659 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root
uuid: "f016cf66408a49599389c20fc4969e4b"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-s11t"
I20260812 06:18:46.974764  5659 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-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:18:46.987207  5659 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.987649  5659 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.988003  5659 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:46.988538  5659 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:46.988579  5659 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.988639  5659 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:46.988786  5659 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.993247  5659 rpc_server.cc:307] RPC server started. Bound to: 127.5.134.193:46167
I20260812 06:18:46.993997  6226 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.134.193:46167 every 8 connection(s)
I20260812 06:18:47.002415  6228 heartbeater.cc:344] Connected to a master server at 127.5.134.254:43977
I20260812 06:18:47.002590  6228 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:47.002920  6228 heartbeater.cc:507] Master 127.5.134.254:43977 requested a full tablet report, sending...
I20260812 06:18:47.003644  6015 ts_manager.cc:194] Registered new tserver with Master: f016cf66408a49599389c20fc4969e4b (127.5.134.193:46167)
I20260812 06:18:47.004177  5659 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01005485s
I20260812 06:18:47.004498  6015 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57950
I20260812 06:18:47.012492  6015 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57952:
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:18:47.021337  6167 tablet_service.cc:1511] Processing CreateTablet for tablet beea6b486762496d9065809f08453951 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7e87965d85bf4b5d924425a2eb9f05c6]), partition=
I20260812 06:18:47.021658  6167 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet beea6b486762496d9065809f08453951. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.023671  6246 tablet_bootstrap.cc:492] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Bootstrap starting.
I20260812 06:18:47.024582  6246 tablet_bootstrap.cc:654] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.025703  6246 tablet_bootstrap.cc:492] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: No bootstrap required, opened a new log
I20260812 06:18:47.025787  6246 ts_tablet_manager.cc:1403] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:47.026207  6246 raft_consensus.cc:359] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f016cf66408a49599389c20fc4969e4b" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 46167 } }
I20260812 06:18:47.026336  6246 raft_consensus.cc:385] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.026373  6246 raft_consensus.cc:740] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f016cf66408a49599389c20fc4969e4b, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.026532  6246 consensus_queue.cc:260] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [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: "f016cf66408a49599389c20fc4969e4b" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 46167 } }
I20260812 06:18:47.026649  6246 raft_consensus.cc:399] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.026690  6246 raft_consensus.cc:493] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.026742  6246 raft_consensus.cc:3060] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.027645  6246 raft_consensus.cc:515] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f016cf66408a49599389c20fc4969e4b" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 46167 } }
I20260812 06:18:47.027803  6246 leader_election.cc:304] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [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: f016cf66408a49599389c20fc4969e4b; no voters: 
I20260812 06:18:47.028028  6246 leader_election.cc:290] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.028185  6248 raft_consensus.cc:2804] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.028396  6246 ts_tablet_manager.cc:1434] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:47.028416  6228 heartbeater.cc:499] Master 127.5.134.254:43977 was elected leader, sending a full tablet report...
I20260812 06:18:47.028739  6248 raft_consensus.cc:697] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 1 LEADER]: Becoming Leader. State: Replica: f016cf66408a49599389c20fc4969e4b, State: Running, Role: LEADER
I20260812 06:18:47.028944  6248 consensus_queue.cc:237] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [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: "f016cf66408a49599389c20fc4969e4b" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 46167 } }
I20260812 06:18:47.030377  6015 catalog_manager.cc:5719] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b reported cstate change: term changed from 0 to 1, leader changed from <none> to f016cf66408a49599389c20fc4969e4b (127.5.134.193). New cstate: current_term: 1 leader_uuid: "f016cf66408a49599389c20fc4969e4b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f016cf66408a49599389c20fc4969e4b" member_type: VOTER last_known_addr { host: "127.5.134.193" port: 46167 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:47.096093  5659 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.009s
I20260812 06:18:47.244606  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushMRSOp(beea6b486762496d9065809f08453951): perf score=19.054940
I20260812 06:18:47.405962  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushMRSOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.161s	user 0.119s	sys 0.041s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":796,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44402,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:47.406545  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling LogGCOp(beea6b486762496d9065809f08453951): free 20743831 bytes of WAL
I20260812 06:18:47.406775  6128 log_reader.cc:385] T beea6b486762496d9065809f08453951: removed 2 log segments from log reader
I20260812 06:18:47.406821  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000001 (ops 1-6)
I20260812 06:18:47.406850  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000002 (ops 7-11)
I20260812 06:18:47.411988  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: LogGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:47.412441  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:47.426484  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.426891  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:47.569448  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.142s	user 0.105s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":471,"lbm_read_time_us":9392,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23729,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":333,"threads_started":5,"update_count":2000}
I20260812 06:18:47.570113  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=12.110812
I20260812 06:18:47.603756  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.033s	user 0.022s	sys 0.008s Metrics: {"bytes_written":13743342,"delete_count":0,"lbm_write_time_us":14453,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:18:47.604454  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951): 16411395 bytes on disk
I20260812 06:18:47.605098  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.605684  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=1.196750
I20260812 06:18:47.622372  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.017s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:18:47.622906  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:47.769912  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.147s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":405,"lbm_read_time_us":9961,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23462,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:18:47.770459  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:47.825922  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.055s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23690,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.826421  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:47.847323  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.847910  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:48.061543  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.213s	user 0.141s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":914,"lbm_read_time_us":15257,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35347,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2500}
I20260812 06:18:48.062331  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:48.112775  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.050s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.113277  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:48.125214  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.125876  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:48.323319  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.197s	user 0.132s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1225,"lbm_read_time_us":12583,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34052,"lbm_writes_lt_1ms":543,"mutex_wait_us":243,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:18:48.324030  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:48.376578  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.052s	user 0.019s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19798,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.377156  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:48.392925  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.393656  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:48.548141  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.153s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":11307,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29136,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:18:48.548794  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:48.605333  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.056s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.606148  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:48.626358  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.626950  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushMRSOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:48.662457  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushMRSOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.035s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":289,"dirs.run_wall_time_us":1247,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1404,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:48.663069  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling LogGCOp(beea6b486762496d9065809f08453951): free 111786314 bytes of WAL
I20260812 06:18:48.663304  6128 log_reader.cc:385] T beea6b486762496d9065809f08453951: removed 11 log segments from log reader
I20260812 06:18:48.663349  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000003 (ops 12-16)
I20260812 06:18:48.663404  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000004 (ops 17-21)
I20260812 06:18:48.663447  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000005 (ops 22-26)
I20260812 06:18:48.663509  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000006 (ops 27-31)
I20260812 06:18:48.663549  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000007 (ops 32-36)
I20260812 06:18:48.663590  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000008 (ops 37-40)
I20260812 06:18:48.663628  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000009 (ops 41-45)
I20260812 06:18:48.663669  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000010 (ops 46-50)
I20260812 06:18:48.663708  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000011 (ops 51-54)
I20260812 06:18:48.663746  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000012 (ops 55-59)
I20260812 06:18:48.663785  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000013 (ops 60-64)
I20260812 06:18:48.689770  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: LogGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:48.690402  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951): 462 bytes on disk
I20260812 06:18:48.690943  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.691421  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=6.157687
I20260812 06:18:48.711968  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.020s	user 0.006s	sys 0.012s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":8252,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:48.712457  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling LogGCOp(beea6b486762496d9065809f08453951): free 8767118 bytes of WAL
I20260812 06:18:48.722997  6128 log_reader.cc:385] T beea6b486762496d9065809f08453951: removed 1 log segments from log reader
I20260812 06:18:48.723078  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000014 (ops 65-69)
I20260812 06:18:48.725874  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: LogGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.013s	user 0.001s	sys 0.002s Metrics: {"spinlock_wait_cycles":22184832}
I20260812 06:18:48.726377  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:48.956112  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.230s	user 0.151s	sys 0.071s Metrics: {"cfile_cache_miss":723,"cfile_cache_miss_bytes":32569391,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":669,"lbm_read_time_us":17005,"lbm_reads_lt_1ms":755,"lbm_write_time_us":38267,"lbm_writes_lt_1ms":733,"mutex_wait_us":78,"peak_mem_usage":86518310,"reinsert_count":0,"spinlock_wait_cycles":692608,"thread_start_us":96,"threads_started":1,"update_count":3450}
I20260812 06:18:48.956856  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=19.056125
I20260812 06:18:49.025787  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.069s	user 0.027s	sys 0.040s Metrics: {"bytes_written":20922560,"delete_count":0,"lbm_write_time_us":24631,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:18:49.026468  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:49.037904  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4489,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.038326  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:49.252622  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.214s	user 0.150s	sys 0.063s Metrics: {"cfile_cache_miss":642,"cfile_cache_miss_bytes":29287347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":957,"lbm_read_time_us":17054,"lbm_reads_lt_1ms":682,"lbm_write_time_us":34634,"lbm_writes_lt_1ms":653,"mutex_wait_us":47,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":3050}
I20260812 06:18:49.253347  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:49.302742  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.049s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21974,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.303397  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:49.314381  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.314963  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:49.481639  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.166s	user 0.101s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":11675,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28999,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:18:49.482216  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:49.544409  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.062s	user 0.033s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23605,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.545012  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:49.556134  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.556897  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:49.745564  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.188s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":14211,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30345,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:18:49.746263  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:49.803097  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.057s	user 0.036s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20587,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.803680  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:49.814703  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.815163  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:50.000842  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.185s	user 0.115s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1407,"lbm_read_time_us":13102,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29494,"lbm_writes_lt_1ms":543,"mutex_wait_us":539,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:50.001513  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:50.054523  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.053s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19327,"lbm_writes_lt_1ms":403,"mutex_wait_us":1,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:50.055085  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:50.082123  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.027s	user 0.014s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.082799  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:50.274667  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.192s	user 0.136s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":14291,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28530,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:18:50.275307  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:50.331529  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.056s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23778,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.332086  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:50.347574  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.348230  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushMRSOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:50.394047  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushMRSOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.046s	user 0.040s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1270,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2154,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:50.394902  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling LogGCOp(beea6b486762496d9065809f08453951): free 132571338 bytes of WAL
I20260812 06:18:50.395196  6128 log_reader.cc:385] T beea6b486762496d9065809f08453951: removed 13 log segments from log reader
I20260812 06:18:50.395272  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000015 (ops 70-74)
I20260812 06:18:50.395329  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000016 (ops 75-79)
I20260812 06:18:50.395393  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000017 (ops 80-84)
I20260812 06:18:50.395437  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000018 (ops 85-88)
I20260812 06:18:50.395474  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000019 (ops 89-93)
I20260812 06:18:50.395514  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000020 (ops 94-98)
I20260812 06:18:50.395555  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000021 (ops 99-103)
I20260812 06:18:50.395594  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000022 (ops 104-108)
I20260812 06:18:50.395634  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000023 (ops 109-113)
I20260812 06:18:50.395744  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000024 (ops 114-118)
I20260812 06:18:50.395789  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000025 (ops 119-123)
I20260812 06:18:50.395826  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000026 (ops 124-128)
I20260812 06:18:50.395866  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000027 (ops 129-132)
I20260812 06:18:50.425701  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: LogGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:50.426139  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=3.181125
I20260812 06:18:50.445631  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.019s	user 0.001s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5357,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.446154  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951): 493 bytes on disk
I20260812 06:18:50.446588  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.447098  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:50.456993  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3642,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.457479  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:50.705014  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.247s	user 0.153s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":420,"lbm_read_time_us":16010,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40303,"lbm_writes_lt_1ms":743,"mutex_wait_us":93,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23040,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:18:50.707809  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=18.063937
I20260812 06:18:50.779547  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.071s	user 0.029s	sys 0.023s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25201,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:50.780083  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:50.793660  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.013s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.794186  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:51.004165  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.209s	user 0.120s	sys 0.090s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":15122,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34350,"lbm_writes_lt_1ms":643,"mutex_wait_us":107,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:18:51.004951  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:51.072037  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.067s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25768,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.072996  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:51.085011  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.085525  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:51.271854  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.186s	user 0.132s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":419,"lbm_read_time_us":12225,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30000,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:51.272547  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:51.333374  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.061s	user 0.023s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20316,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.334004  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:51.345180  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.345708  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:51.530164  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.184s	user 0.113s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":108,"lbm_read_time_us":13014,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32333,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:51.531034  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:51.588378  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.057s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20776,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.589059  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:51.599843  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.600297  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:51.789144  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.189s	user 0.117s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":13153,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30420,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":139648,"update_count":2500}
I20260812 06:18:51.789894  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:51.845079  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.055s	user 0.043s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23383,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.845592  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:51.869612  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.870198  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushMRSOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:51.904150  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushMRSOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1726,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:51.904889  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling LogGCOp(beea6b486762496d9065809f08453951): free 112692558 bytes of WAL
I20260812 06:18:51.905258  6128 log_reader.cc:385] T beea6b486762496d9065809f08453951: removed 11 log segments from log reader
I20260812 06:18:51.905364  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000028 (ops 133-137)
I20260812 06:18:51.905411  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000029 (ops 138-142)
I20260812 06:18:51.905509  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000030 (ops 143-147)
I20260812 06:18:51.905550  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000031 (ops 148-152)
I20260812 06:18:51.905592  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000032 (ops 153-157)
I20260812 06:18:51.905628  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000033 (ops 158-162)
I20260812 06:18:51.905664  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000034 (ops 163-167)
I20260812 06:18:51.905762  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000035 (ops 168-172)
I20260812 06:18:51.905807  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000036 (ops 173-177)
I20260812 06:18:51.905841  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000037 (ops 178-182)
I20260812 06:18:51.905881  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000038 (ops 183-187)
I20260812 06:18:51.938725  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: LogGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.034s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:51.939399  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=3.181125
I20260812 06:18:51.955327  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":6259,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:18:51.955871  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=1.196750
I20260812 06:18:51.969012  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4406,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:51.969723  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling LogGCOp(beea6b486762496d9065809f08453951): free 12018004 bytes of WAL
I20260812 06:18:51.970057  6128 log_reader.cc:385] T beea6b486762496d9065809f08453951: removed 1 log segments from log reader
I20260812 06:18:51.970160  6128 log.cc:1079] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: Deleting log segment in path: /tmp/dist-test-taskdSLGz5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521314017-5659-0/minicluster-data/ts-0-root/wals/beea6b486762496d9065809f08453951/wal-000000039 (ops 188-192)
I20260812 06:18:51.973635  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: LogGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:51.974099  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951): 462 bytes on disk
I20260812 06:18:51.975082  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: UndoDeltaBlockGCOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.975778  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:52.206120  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.230s	user 0.150s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":248,"lbm_read_time_us":13978,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41783,"lbm_writes_lt_1ms":743,"mutex_wait_us":677,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:52.206892  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=14.095187
I20260812 06:18:52.225950  5659 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.130s	user 1.913s	sys 0.208s
I20260812 06:18:52.245620  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.038s	user 0.025s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18282,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.246353  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951): perf score=2.188937
I20260812 06:18:52.259855  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: FlushDeltaMemStoresOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.260326  6232 maintenance_manager.cc:419] P f016cf66408a49599389c20fc4969e4b: Scheduling MajorDeltaCompactionOp(beea6b486762496d9065809f08453951): perf score=1.000000
I20260812 06:18:52.271692  5659 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.045s	user 0.002s	sys 0.000s
I20260812 06:18:52.272357  5659 tablet_server.cc:179] TabletServer@127.5.134.193:0 shutting down...
I20260812 06:18:52.407881  6128 maintenance_manager.cc:643] P f016cf66408a49599389c20fc4969e4b: MajorDeltaCompactionOp(beea6b486762496d9065809f08453951) complete. Timing: real 0.147s	user 0.102s	sys 0.043s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512299,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":416,"lbm_read_time_us":9824,"lbm_reads_lt_1ms":518,"lbm_write_time_us":25131,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.409387  5659 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:52.409822  5659 tablet_replica.cc:333] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b: stopping tablet replica
I20260812 06:18:52.409971  5659 raft_consensus.cc:2243] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.410179  5659 raft_consensus.cc:2272] T beea6b486762496d9065809f08453951 P f016cf66408a49599389c20fc4969e4b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.427675  5659 tablet_server.cc:196] TabletServer@127.5.134.193:0 shutdown complete.
I20260812 06:18:52.454823  5659 master.cc:562] Master@127.5.134.254:43977 shutting down...
I20260812 06:18:52.459064  5659 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.459286  5659 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.459400  5659 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5dba0fa059994effb9c54dded3792325: stopping tablet replica
I20260812 06:18:52.472157  5659 master.cc:584] Master@127.5.134.254:43977 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5690 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11240 ms total)

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