[==========] 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:27.439805 14637 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.75.126:37807
I20260812 06:18:27.440904 14637 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:27.441515 14637 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.448628 14645 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:27.448678 14637 server_base.cc:1061] running on GCE node
W20260812 06:18:27.448580 14647 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:27.448964 14643 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:27.449515 14637 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.449661 14637 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:27.449698 14637 hybrid_clock.cc:648] HybridClock initialized: now 1786515507449697 us; error 0 us; skew 500 ppm
I20260812 06:18:27.451625 14637 webserver.cc:533] Webserver started at http://127.14.75.126:40119/ using document root <none> and password file <none>
I20260812 06:18:27.452152 14637 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.452207 14637 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.452400 14637 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.454138 14637 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/master-0-root/instance:
uuid: "68a96cf0f19c4d979196636235a16627"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-3h5h"
I20260812 06:18:27.457696 14637 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:27.459733 14656 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:27.460755 14637 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:27.460906 14637 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/master-0-root
uuid: "68a96cf0f19c4d979196636235a16627"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-3h5h"
I20260812 06:18:27.461014 14637 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-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:27.483515 14637 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.484138 14637 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:27.484292 14637 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.492513 14637 rpc_server.cc:307] RPC server started. Bound to: 127.14.75.126:37807
I20260812 06:18:27.492518 14744 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.75.126:37807 every 8 connection(s)
I20260812 06:18:27.495035 14746 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:27.500705 14746 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627: Bootstrap starting.
I20260812 06:18:27.503159 14746 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.504132 14746 log.cc:826] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.506006 14746 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627: No bootstrap required, opened a new log
I20260812 06:18:27.508925 14746 raft_consensus.cc:359] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a96cf0f19c4d979196636235a16627" member_type: VOTER }
I20260812 06:18:27.509207 14746 raft_consensus.cc:385] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.509310 14746 raft_consensus.cc:740] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 68a96cf0f19c4d979196636235a16627, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.510007 14746 consensus_queue.cc:260] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [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: "68a96cf0f19c4d979196636235a16627" member_type: VOTER }
I20260812 06:18:27.510210 14746 raft_consensus.cc:399] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.510291 14746 raft_consensus.cc:493] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.510449 14746 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.511291 14746 raft_consensus.cc:515] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a96cf0f19c4d979196636235a16627" member_type: VOTER }
I20260812 06:18:27.511771 14746 leader_election.cc:304] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [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: 68a96cf0f19c4d979196636235a16627; no voters: 
I20260812 06:18:27.512147 14746 leader_election.cc:290] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.512306 14749 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.512578 14749 raft_consensus.cc:697] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 1 LEADER]: Becoming Leader. State: Replica: 68a96cf0f19c4d979196636235a16627, State: Running, Role: LEADER
I20260812 06:18:27.513067 14749 consensus_queue.cc:237] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [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: "68a96cf0f19c4d979196636235a16627" member_type: VOTER }
I20260812 06:18:27.513279 14746 sys_catalog.cc:565] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.514993 14750 sys_catalog.cc:455] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "68a96cf0f19c4d979196636235a16627" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a96cf0f19c4d979196636235a16627" member_type: VOTER } }
I20260812 06:18:27.514956 14753 sys_catalog.cc:455] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 68a96cf0f19c4d979196636235a16627. Latest consensus state: current_term: 1 leader_uuid: "68a96cf0f19c4d979196636235a16627" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a96cf0f19c4d979196636235a16627" member_type: VOTER } }
I20260812 06:18:27.515106 14750 sys_catalog.cc:458] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.515106 14753 sys_catalog.cc:458] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.515479 14773 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.515620 14637 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:27.518050 14773 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.523003 14773 catalog_manager.cc:1383] Generated new cluster ID: 7bc84ac507bf4119aaaa5b19e1844a4b
I20260812 06:18:27.523089 14773 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.545792 14773 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.547070 14773 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.553262 14773 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627: Generated new TSK 0
I20260812 06:18:27.553999 14773 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.580693 14637 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.584316 14791 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:27.584421 14788 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:27.584436 14637 server_base.cc:1061] running on GCE node
W20260812 06:18:27.584591 14787 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:27.584800 14637 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.584887 14637 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:27.584944 14637 hybrid_clock.cc:648] HybridClock initialized: now 1786515507584942 us; error 0 us; skew 500 ppm
I20260812 06:18:27.585901 14637 webserver.cc:533] Webserver started at http://127.14.75.65:41527/ using document root <none> and password file <none>
I20260812 06:18:27.586090 14637 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.586184 14637 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.586287 14637 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.586706 14637 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/instance:
uuid: "d935e78d48e04ad286b4cb99ff591ddf"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-3h5h"
I20260812 06:18:27.588274 14637 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:18:27.589386 14799 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:27.589679 14637 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:27.589741 14637 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root
uuid: "d935e78d48e04ad286b4cb99ff591ddf"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-3h5h"
I20260812 06:18:27.589834 14637 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-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:27.609596 14637 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.610198 14637 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.610802 14637 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.611866 14637 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.611927 14637 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.612015 14637 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.612061 14637 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.619858 14637 rpc_server.cc:307] RPC server started. Bound to: 127.14.75.65:37635
I20260812 06:18:27.619897 14892 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.75.65:37635 every 8 connection(s)
I20260812 06:18:27.635540 14893 heartbeater.cc:344] Connected to a master server at 127.14.75.126:37807
I20260812 06:18:27.635814 14893 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.636343 14893 heartbeater.cc:507] Master 127.14.75.126:37807 requested a full tablet report, sending...
I20260812 06:18:27.637907 14686 ts_manager.cc:194] Registered new tserver with Master: d935e78d48e04ad286b4cb99ff591ddf (127.14.75.65:37635)
I20260812 06:18:27.638505 14637 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017911036s
I20260812 06:18:27.639497 14686 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48188
I20260812 06:18:27.648322 14686 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48192:
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:27.662864 14841 tablet_service.cc:1511] Processing CreateTablet for tablet 9027ebfe039b4462ac5f13f9e5fd3150 (DEFAULT_TABLE table=heavy-update-compaction-test [id=09532cebe94240a598dfc99423d5a503]), partition=
I20260812 06:18:27.663439 14841 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9027ebfe039b4462ac5f13f9e5fd3150. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.665915 14912 tablet_bootstrap.cc:492] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Bootstrap starting.
I20260812 06:18:27.667366 14912 tablet_bootstrap.cc:654] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.668521 14912 tablet_bootstrap.cc:492] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: No bootstrap required, opened a new log
I20260812 06:18:27.668653 14912 ts_tablet_manager.cc:1403] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.669186 14912 raft_consensus.cc:359] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d935e78d48e04ad286b4cb99ff591ddf" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 37635 } }
I20260812 06:18:27.669312 14912 raft_consensus.cc:385] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.669358 14912 raft_consensus.cc:740] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d935e78d48e04ad286b4cb99ff591ddf, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.669499 14912 consensus_queue.cc:260] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [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: "d935e78d48e04ad286b4cb99ff591ddf" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 37635 } }
I20260812 06:18:27.669608 14912 raft_consensus.cc:399] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.669665 14912 raft_consensus.cc:493] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.669719 14912 raft_consensus.cc:3060] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.670461 14912 raft_consensus.cc:515] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d935e78d48e04ad286b4cb99ff591ddf" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 37635 } }
I20260812 06:18:27.670629 14912 leader_election.cc:304] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [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: d935e78d48e04ad286b4cb99ff591ddf; no voters: 
I20260812 06:18:27.670867 14912 leader_election.cc:290] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.670991 14914 raft_consensus.cc:2804] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.671259 14914 raft_consensus.cc:697] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 1 LEADER]: Becoming Leader. State: Replica: d935e78d48e04ad286b4cb99ff591ddf, State: Running, Role: LEADER
I20260812 06:18:27.671329 14912 ts_tablet_manager.cc:1434] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:27.671440 14914 consensus_queue.cc:237] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [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: "d935e78d48e04ad286b4cb99ff591ddf" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 37635 } }
I20260812 06:18:27.671840 14893 heartbeater.cc:499] Master 127.14.75.126:37807 was elected leader, sending a full tablet report...
I20260812 06:18:27.674783 14686 catalog_manager.cc:5719] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf reported cstate change: term changed from 0 to 1, leader changed from <none> to d935e78d48e04ad286b4cb99ff591ddf (127.14.75.65). New cstate: current_term: 1 leader_uuid: "d935e78d48e04ad286b4cb99ff591ddf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d935e78d48e04ad286b4cb99ff591ddf" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 37635 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.736364 14637 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.019s	sys 0.004s
I20260812 06:18:27.871039 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=15.086190
I20260812 06:18:28.032904 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.162s	user 0.137s	sys 0.024s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":376,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":962,"drs_written":1,"lbm_read_time_us":140,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38611,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":489728,"thread_start_us":133,"threads_started":1,"update_count":1050}
I20260812 06:18:28.034385 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150): free 20743880 bytes of WAL
I20260812 06:18:28.034719 14807 log_reader.cc:385] T 9027ebfe039b4462ac5f13f9e5fd3150: removed 2 log segments from log reader
I20260812 06:18:28.034797 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000001 (ops 1-6)
I20260812 06:18:28.034858 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000002 (ops 7-11)
I20260812 06:18:28.040328 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:28.040803 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:28.059217 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.018s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5250,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.059705 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:28.180363 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.121s	user 0.082s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":7054,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20550,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":312,"threads_started":5,"update_count":1500}
I20260812 06:18:28.181066 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150): 16411397 bytes on disk
I20260812 06:18:28.181716 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.182307 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:28.230288 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.048s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16820,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.230846 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:28.246110 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.246628 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:28.386238 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.139s	user 0.111s	sys 0.027s 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":181,"lbm_read_time_us":11886,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25228,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:18:28.386827 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:28.438716 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.052s	user 0.016s	sys 0.025s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15605,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.439203 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:28.450018 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.011s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4172,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.450433 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:28.620878 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.170s	user 0.119s	sys 0.043s 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":208,"lbm_read_time_us":10539,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30053,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":66048,"update_count":2000}
I20260812 06:18:28.621575 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:28.656976 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.035s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.657486 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:28.768663 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.111s	user 0.084s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":293,"lbm_read_time_us":7249,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19154,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:28.769218 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:28.821049 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.052s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16686,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.821552 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:28.834695 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.835353 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:28.977826 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.142s	user 0.107s	sys 0.032s 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":203,"lbm_read_time_us":10132,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27845,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:18:28.978600 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:29.035414 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.057s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17563,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.036013 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:29.048027 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.048578 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:29.199576 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.151s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":10478,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24476,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:29.200248 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:29.246160 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.046s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.246707 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:29.257740 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.258366 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:29.376977 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.118s	user 0.097s	sys 0.018s 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":1007,"lbm_read_time_us":7711,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23797,"lbm_writes_lt_1ms":443,"mutex_wait_us":358,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.377493 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:29.421883 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.044s	user 0.018s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20983,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.422456 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:29.433771 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3853,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.434297 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:29.464617 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.030s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1538,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1540,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:29.465729 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150): free 121006437 bytes of WAL
I20260812 06:18:29.465979 14807 log_reader.cc:385] T 9027ebfe039b4462ac5f13f9e5fd3150: removed 12 log segments from log reader
I20260812 06:18:29.466027 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000003 (ops 12-16)
I20260812 06:18:29.466089 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000004 (ops 17-20)
I20260812 06:18:29.466140 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000005 (ops 21-25)
I20260812 06:18:29.466215 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000006 (ops 26-30)
I20260812 06:18:29.466260 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000007 (ops 31-35)
I20260812 06:18:29.466302 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000008 (ops 36-40)
I20260812 06:18:29.466344 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000009 (ops 41-45)
I20260812 06:18:29.466387 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000010 (ops 46-50)
I20260812 06:18:29.466430 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000011 (ops 51-55)
I20260812 06:18:29.466475 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000012 (ops 56-60)
I20260812 06:18:29.466517 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000013 (ops 61-65)
I20260812 06:18:29.466566 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000014 (ops 66-70)
I20260812 06:18:29.512689 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.047s	user 0.000s	sys 0.043s Metrics: {}
I20260812 06:18:29.513984 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=6.157687
I20260812 06:18:29.565678 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.051s	user 0.033s	sys 0.017s Metrics: {"bytes_written":7671762,"delete_count":0,"lbm_write_time_us":22203,"lbm_writes_lt_1ms":190,"reinsert_count":0,"update_count":935}
I20260812 06:18:29.566764 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:29.940519 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.373s	user 0.292s	sys 0.080s Metrics: {"cfile_cache_miss":620,"cfile_cache_miss_bytes":28343905,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1920,"lbm_read_time_us":28123,"lbm_reads_lt_1ms":652,"lbm_write_time_us":80935,"lbm_writes_lt_1ms":630,"peak_mem_usage":73968633,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":1062,"threads_started":6,"update_count":2935}
I20260812 06:18:29.942152 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150): 473 bytes on disk
I20260812 06:18:29.943118 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":176,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.944725 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=15.087375
I20260812 06:18:30.072373 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.127s	user 0.085s	sys 0.032s Metrics: {"bytes_written":16943223,"delete_count":0,"lbm_write_time_us":54505,"lbm_writes_lt_1ms":416,"reinsert_count":0,"update_count":2065}
I20260812 06:18:30.073524 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=6.157687
I20260812 06:18:30.108767 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.035s	user 0.026s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14069,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:30.109421 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:30.302606 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.193s	user 0.140s	sys 0.052s Metrics: {"cfile_cache_miss":645,"cfile_cache_miss_bytes":29410423,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":457,"lbm_read_time_us":14035,"lbm_reads_lt_1ms":681,"lbm_write_time_us":40384,"lbm_writes_lt_1ms":656,"mutex_wait_us":24,"peak_mem_usage":77116311,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":3065}
I20260812 06:18:30.303364 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=14.095187
I20260812 06:18:30.354727 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.051s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22580,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.355310 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:30.366818 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.367295 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:30.536626 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.169s	user 0.123s	sys 0.037s 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":253,"lbm_read_time_us":10574,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32650,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:30.537264 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=14.095187
I20260812 06:18:30.583041 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.046s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.583586 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:30.724762 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.141s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":555,"lbm_read_time_us":8347,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25238,"lbm_writes_lt_1ms":443,"mutex_wait_us":245,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:18:30.725557 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:30.762745 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.037s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15651,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.763522 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:30.781965 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.782490 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:30.913496 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.131s	user 0.098s	sys 0.033s 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":176,"lbm_read_time_us":7558,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26369,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:18:30.914191 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:30.966133 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.052s	user 0.030s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":26071,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.966728 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:30.980175 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.980823 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:31.120370 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.139s	user 0.090s	sys 0.049s 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":176,"lbm_read_time_us":8291,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29304,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:31.121222 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:31.165787 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.044s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15826,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.166317 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:31.179540 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.180295 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:31.214394 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1600,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1846,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:31.215166 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150): free 120100280 bytes of WAL
I20260812 06:18:31.215406 14807 log_reader.cc:385] T 9027ebfe039b4462ac5f13f9e5fd3150: removed 12 log segments from log reader
I20260812 06:18:31.215454 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000015 (ops 71-75)
I20260812 06:18:31.215510 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000016 (ops 76-80)
I20260812 06:18:31.215585 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000017 (ops 81-84)
I20260812 06:18:31.215626 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000018 (ops 85-89)
I20260812 06:18:31.215668 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000019 (ops 90-94)
I20260812 06:18:31.215713 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000020 (ops 95-98)
I20260812 06:18:31.215754 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000021 (ops 99-103)
I20260812 06:18:31.215795 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000022 (ops 104-108)
I20260812 06:18:31.215837 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000023 (ops 109-112)
I20260812 06:18:31.215878 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000024 (ops 113-117)
I20260812 06:18:31.215919 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000025 (ops 118-122)
I20260812 06:18:31.215969 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000026 (ops 123-127)
I20260812 06:18:31.246233 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:31.246814 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=4.173312
I20260812 06:18:31.261673 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":5497489,"delete_count":0,"lbm_write_time_us":6128,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:18:31.262184 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150): 462 bytes on disk
I20260812 06:18:31.262632 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.263163 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.196750
I20260812 06:18:31.273000 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3437,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:31.273563 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:31.456511 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.183s	user 0.139s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877309,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2234,"lbm_read_time_us":12598,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35950,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:31.457276 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=14.095187
I20260812 06:18:31.517306 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.060s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26227,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.517776 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=3.181125
I20260812 06:18:31.529441 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:31.529922 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:31.543104 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5003,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.543702 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:31.707682 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.164s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":388,"lbm_read_time_us":13693,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34050,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:18:31.708240 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=14.095187
I20260812 06:18:31.754858 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19634,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.755468 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:31.766571 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.767225 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:31.921252 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.154s	user 0.111s	sys 0.042s 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":578,"lbm_read_time_us":10856,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29829,"lbm_writes_lt_1ms":543,"mutex_wait_us":309,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:31.922040 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=11.118625
I20260812 06:18:31.952714 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.030s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":13424,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.953230 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:31.965852 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.966377 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:32.116397 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.150s	user 0.126s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":9927,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27558,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:18:32.117094 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:32.152110 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.035s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.152621 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:32.168651 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.169342 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:32.316213 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.147s	user 0.114s	sys 0.029s 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":307,"lbm_read_time_us":8854,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25572,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:18:32.317037 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:32.368227 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.051s	user 0.030s	sys 0.005s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16960,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.368805 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:32.384542 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.385303 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:32.512283 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.127s	user 0.106s	sys 0.020s 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":439,"lbm_read_time_us":7973,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26804,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:32.512771 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=10.126437
I20260812 06:18:32.558162 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.045s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17593,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.558691 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:32.570592 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.571341 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:32.601652 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushMRSOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.030s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":288,"dirs.run_wall_time_us":1558,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1455,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:32.602334 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150): free 124257561 bytes of WAL
I20260812 06:18:32.602555 14807 log_reader.cc:385] T 9027ebfe039b4462ac5f13f9e5fd3150: removed 12 log segments from log reader
I20260812 06:18:32.602620 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000027 (ops 128-132)
I20260812 06:18:32.602674 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000028 (ops 133-137)
I20260812 06:18:32.602737 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000029 (ops 138-142)
I20260812 06:18:32.602777 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000030 (ops 143-147)
I20260812 06:18:32.602813 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000031 (ops 148-152)
I20260812 06:18:32.602850 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000032 (ops 153-157)
I20260812 06:18:32.602887 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000033 (ops 158-162)
I20260812 06:18:32.602924 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000034 (ops 163-166)
I20260812 06:18:32.602960 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000035 (ops 167-171)
I20260812 06:18:32.602996 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000036 (ops 172-176)
I20260812 06:18:32.603032 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000037 (ops 177-181)
I20260812 06:18:32.603068 14807 log.cc:1079] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/9027ebfe039b4462ac5f13f9e5fd3150/wal-000000038 (ops 182-186)
I20260812 06:18:32.630280 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: LogGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:32.630681 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150): 463 bytes on disk
I20260812 06:18:32.631110 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: UndoDeltaBlockGCOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.631685 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=3.181125
I20260812 06:18:32.651351 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.020s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7160,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:32.651806 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:32.661963 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.662451 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:32.843340 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.181s	user 0.139s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":378,"lbm_read_time_us":13499,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34277,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":64768,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:32.844110 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=14.095187
I20260812 06:18:32.897410 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.053s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23643,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.898030 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=2.188937
I20260812 06:18:32.916656 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: FlushDeltaMemStoresOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.917483 14894 maintenance_manager.cc:419] P d935e78d48e04ad286b4cb99ff591ddf: Scheduling MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150): perf score=1.000000
I20260812 06:18:32.927556 14637 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.191s	user 1.894s	sys 0.133s
I20260812 06:18:32.990967 14637 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.002s	sys 0.000s
I20260812 06:18:32.991654 14637 tablet_server.cc:179] TabletServer@127.14.75.65:0 shutting down...
I20260812 06:18:33.052469 14807 maintenance_manager.cc:643] P d935e78d48e04ad286b4cb99ff591ddf: MajorDeltaCompactionOp(9027ebfe039b4462ac5f13f9e5fd3150) complete. Timing: real 0.135s	user 0.105s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":915,"lbm_read_time_us":12517,"lbm_reads_lt_1ms":560,"lbm_write_time_us":25972,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:33.053409 14637 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:33.053910 14637 tablet_replica.cc:333] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf: stopping tablet replica
I20260812 06:18:33.054162 14637 raft_consensus.cc:2243] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.054412 14637 raft_consensus.cc:2272] T 9027ebfe039b4462ac5f13f9e5fd3150 P d935e78d48e04ad286b4cb99ff591ddf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.078912 14637 tablet_server.cc:196] TabletServer@127.14.75.65:0 shutdown complete.
I20260812 06:18:33.100410 14637 master.cc:562] Master@127.14.75.126:37807 shutting down...
I20260812 06:18:33.104544 14637 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.104754 14637 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.104880 14637 tablet_replica.cc:333] T 00000000000000000000000000000000 P 68a96cf0f19c4d979196636235a16627: stopping tablet replica
I20260812 06:18:33.117648 14637 master.cc:584] Master@127.14.75.126:37807 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5767 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:33.207644 14637 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.75.126:34983
I20260812 06:18:33.208114 14637 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.211218 14943 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:33.211324 14945 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:33.211236 14637 server_base.cc:1061] running on GCE node
W20260812 06:18:33.211449 14941 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:33.211752 14637 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.211802 14637 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:33.211820 14637 hybrid_clock.cc:648] HybridClock initialized: now 1786515513211820 us; error 0 us; skew 500 ppm
I20260812 06:18:33.212814 14637 webserver.cc:533] Webserver started at http://127.14.75.126:38869/ using document root <none> and password file <none>
I20260812 06:18:33.213116 14637 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.213176 14637 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.213236 14637 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.213618 14637 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/master-0-root/instance:
uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-3h5h"
I20260812 06:18:33.215317 14637 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:33.216375 14953 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:33.216655 14637 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:33.216765 14637 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/master-0-root
uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-3h5h"
I20260812 06:18:33.216944 14637 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-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:33.230296 14637 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.230767 14637 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.235798 14637 rpc_server.cc:307] RPC server started. Bound to: 127.14.75.126:34983
I20260812 06:18:33.238636 15030 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.75.126:34983 every 8 connection(s)
I20260812 06:18:33.239454 15031 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:33.247263 15031 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99: Bootstrap starting.
I20260812 06:18:33.248129 15031 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.249361 15031 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99: No bootstrap required, opened a new log
I20260812 06:18:33.249768 15031 raft_consensus.cc:359] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" member_type: VOTER }
I20260812 06:18:33.249871 15031 raft_consensus.cc:385] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.249895 15031 raft_consensus.cc:740] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ad3eb555b78c4e1a9a7cb75d0a1e0d99, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.250073 15031 consensus_queue.cc:260] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [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: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" member_type: VOTER }
I20260812 06:18:33.250169 15031 raft_consensus.cc:399] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.250197 15031 raft_consensus.cc:493] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.250231 15031 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.250954 15031 raft_consensus.cc:515] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" member_type: VOTER }
I20260812 06:18:33.251148 15031 leader_election.cc:304] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [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: ad3eb555b78c4e1a9a7cb75d0a1e0d99; no voters: 
I20260812 06:18:33.251475 15031 leader_election.cc:290] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.251654 15035 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.251899 15035 raft_consensus.cc:697] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 1 LEADER]: Becoming Leader. State: Replica: ad3eb555b78c4e1a9a7cb75d0a1e0d99, State: Running, Role: LEADER
I20260812 06:18:33.252102 15035 consensus_queue.cc:237] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [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: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" member_type: VOTER }
I20260812 06:18:33.252125 15031 sys_catalog.cc:565] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:33.252677 15038 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" member_type: VOTER } }
I20260812 06:18:33.252866 15038 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.253178 15040 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ad3eb555b78c4e1a9a7cb75d0a1e0d99. Latest consensus state: current_term: 1 leader_uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3eb555b78c4e1a9a7cb75d0a1e0d99" member_type: VOTER } }
I20260812 06:18:33.253429 15044 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:33.253432 15040 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.254585 15044 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:33.254840 14637 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:33.256796 15044 catalog_manager.cc:1383] Generated new cluster ID: 260c40eb3f414bef8d5b7767c4edb1c7
I20260812 06:18:33.256887 15044 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:33.264358 15044 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:33.264986 15044 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:33.272886 15044 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99: Generated new TSK 0
I20260812 06:18:33.273085 15044 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:33.287452 14637 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.289981 15066 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:33.290073 14637 server_base.cc:1061] running on GCE node
W20260812 06:18:33.290378 15063 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:33.290396 15064 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:33.290702 14637 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.290771 14637 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:33.290798 14637 hybrid_clock.cc:648] HybridClock initialized: now 1786515513290797 us; error 0 us; skew 500 ppm
I20260812 06:18:33.291580 14637 webserver.cc:533] Webserver started at http://127.14.75.65:39533/ using document root <none> and password file <none>
I20260812 06:18:33.291755 14637 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.291826 14637 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.291910 14637 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.292333 14637 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/instance:
uuid: "756d9b976cdd4630b215a439973d0d3d"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-3h5h"
I20260812 06:18:33.293991 14637 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:33.295009 15074 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:33.295301 14637 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:33.295413 14637 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root
uuid: "756d9b976cdd4630b215a439973d0d3d"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-3h5h"
I20260812 06:18:33.295521 14637 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-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:33.316466 14637 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.316970 14637 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.317341 14637 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:33.317839 14637 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:33.317902 14637 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.317968 14637 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:33.318003 14637 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.322834 14637 rpc_server.cc:307] RPC server started. Bound to: 127.14.75.65:38967
I20260812 06:18:33.323375 15182 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.75.65:38967 every 8 connection(s)
I20260812 06:18:33.332510 15183 heartbeater.cc:344] Connected to a master server at 127.14.75.126:34983
I20260812 06:18:33.332635 15183 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:33.332994 15183 heartbeater.cc:507] Master 127.14.75.126:34983 requested a full tablet report, sending...
I20260812 06:18:33.333775 14976 ts_manager.cc:194] Registered new tserver with Master: 756d9b976cdd4630b215a439973d0d3d (127.14.75.65:38967)
I20260812 06:18:33.334470 14976 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35522
I20260812 06:18:33.334697 14637 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011107686s
I20260812 06:18:33.342231 14976 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35536:
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:33.351100 15118 tablet_service.cc:1511] Processing CreateTablet for tablet cbb963b3a75b4b74a98eed8a6bfc530d (DEFAULT_TABLE table=heavy-update-compaction-test [id=7007a2a73e3a43cfac53565a918fd8d3]), partition=
I20260812 06:18:33.351440 15118 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cbb963b3a75b4b74a98eed8a6bfc530d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.353838 15198 tablet_bootstrap.cc:492] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Bootstrap starting.
I20260812 06:18:33.354830 15198 tablet_bootstrap.cc:654] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.355916 15198 tablet_bootstrap.cc:492] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: No bootstrap required, opened a new log
I20260812 06:18:33.356029 15198 ts_tablet_manager.cc:1403] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:33.356627 15198 raft_consensus.cc:359] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "756d9b976cdd4630b215a439973d0d3d" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 38967 } }
I20260812 06:18:33.356750 15198 raft_consensus.cc:385] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.356789 15198 raft_consensus.cc:740] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 756d9b976cdd4630b215a439973d0d3d, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.356971 15198 consensus_queue.cc:260] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [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: "756d9b976cdd4630b215a439973d0d3d" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 38967 } }
I20260812 06:18:33.357048 15198 raft_consensus.cc:399] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.357072 15198 raft_consensus.cc:493] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.357107 15198 raft_consensus.cc:3060] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.357810 15198 raft_consensus.cc:515] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "756d9b976cdd4630b215a439973d0d3d" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 38967 } }
I20260812 06:18:33.357928 15198 leader_election.cc:304] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [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: 756d9b976cdd4630b215a439973d0d3d; no voters: 
I20260812 06:18:33.358095 15198 leader_election.cc:290] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.358244 15200 raft_consensus.cc:2804] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.358434 15183 heartbeater.cc:499] Master 127.14.75.126:34983 was elected leader, sending a full tablet report...
I20260812 06:18:33.358467 15200 raft_consensus.cc:697] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 1 LEADER]: Becoming Leader. State: Replica: 756d9b976cdd4630b215a439973d0d3d, State: Running, Role: LEADER
I20260812 06:18:33.358428 15198 ts_tablet_manager.cc:1434] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:33.358682 15200 consensus_queue.cc:237] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [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: "756d9b976cdd4630b215a439973d0d3d" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 38967 } }
I20260812 06:18:33.359942 14976 catalog_manager.cc:5719] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d reported cstate change: term changed from 0 to 1, leader changed from <none> to 756d9b976cdd4630b215a439973d0d3d (127.14.75.65). New cstate: current_term: 1 leader_uuid: "756d9b976cdd4630b215a439973d0d3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "756d9b976cdd4630b215a439973d0d3d" member_type: VOTER last_known_addr { host: "127.14.75.65" port: 38967 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:33.419888 14637 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.010s	sys 0.012s
I20260812 06:18:33.574150 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=19.054940
I20260812 06:18:33.725014 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.151s	user 0.122s	sys 0.028s Metrics: {"bytes_written":13045918,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":919,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39311,"lbm_writes_lt_1ms":775,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":12032,"update_count":1590}
I20260812 06:18:33.725754 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): free 20290830 bytes of WAL
I20260812 06:18:33.726038 15082 log_reader.cc:385] T cbb963b3a75b4b74a98eed8a6bfc530d: removed 2 log segments from log reader
I20260812 06:18:33.726092 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000001 (ops 1-6)
I20260812 06:18:33.726154 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000002 (ops 7-10)
I20260812 06:18:33.731066 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:33.731475 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:33.747478 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.016s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3634,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:33.747997 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): 16411398 bytes on disk
I20260812 06:18:33.748591 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.749073 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:33.762516 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5243,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.762977 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:33.930222 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.167s	user 0.123s	sys 0.042s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774782,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":517,"lbm_read_time_us":11574,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31093,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":357,"threads_started":5,"update_count":2500}
I20260812 06:18:33.930855 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:33.980396 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.049s	user 0.024s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19600,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.981027 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:33.996215 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.996919 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:34.152511 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.155s	user 0.110s	sys 0.041s 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":733,"lbm_read_time_us":9795,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29359,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:34.153311 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=12.110812
I20260812 06:18:34.215112 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.062s	user 0.021s	sys 0.024s Metrics: {"bytes_written":14194598,"delete_count":0,"lbm_write_time_us":22931,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":347,"reinsert_count":0,"update_count":1730}
I20260812 06:18:34.215646 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=5.165500
I20260812 06:18:34.233773 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6317972,"delete_count":0,"lbm_write_time_us":6850,"lbm_writes_lt_1ms":157,"reinsert_count":0,"update_count":770}
I20260812 06:18:34.234326 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:34.414040 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.180s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":75,"lbm_read_time_us":11809,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30647,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:34.414598 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:34.470031 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.055s	user 0.022s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25208,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.470566 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:34.482663 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.483090 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:34.665944 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.183s	user 0.107s	sys 0.072s 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":250,"lbm_read_time_us":12988,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29947,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:18:34.666563 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:34.728446 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.062s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21109,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.729090 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:34.740173 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.740738 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:34.927035 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.186s	user 0.133s	sys 0.053s 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":1263,"lbm_read_time_us":12894,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31883,"lbm_writes_lt_1ms":543,"mutex_wait_us":724,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2023424,"update_count":2500}
I20260812 06:18:34.927884 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=10.126437
I20260812 06:18:34.962605 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15208,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.963339 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:34.979192 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.979748 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:35.022559 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.043s	user 0.031s	sys 0.007s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1588,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2363,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:35.023363 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): free 120553386 bytes of WAL
I20260812 06:18:35.023628 15082 log_reader.cc:385] T cbb963b3a75b4b74a98eed8a6bfc530d: removed 12 log segments from log reader
I20260812 06:18:35.023699 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000003 (ops 11-15)
I20260812 06:18:35.023756 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000004 (ops 16-20)
I20260812 06:18:35.023813 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000005 (ops 21-25)
I20260812 06:18:35.023855 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000006 (ops 26-30)
I20260812 06:18:35.023895 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000007 (ops 31-35)
I20260812 06:18:35.023936 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000008 (ops 36-40)
I20260812 06:18:35.023975 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000009 (ops 41-44)
I20260812 06:18:35.024014 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000010 (ops 45-49)
I20260812 06:18:35.024053 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000011 (ops 50-54)
I20260812 06:18:35.024093 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000012 (ops 55-59)
I20260812 06:18:35.024138 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000013 (ops 60-64)
I20260812 06:18:35.024178 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000014 (ops 65-68)
I20260812 06:18:35.048054 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:35.048520 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): 462 bytes on disk
I20260812 06:18:35.049055 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:18:35.049568 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:35.071719 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.022s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.072167 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:35.082306 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.082803 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:35.291181 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.208s	user 0.123s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":401,"lbm_read_time_us":13371,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37556,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":191,"threads_started":1,"update_count":3000}
I20260812 06:18:35.292030 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:35.365305 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.073s	user 0.052s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":31447,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.365937 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:35.388227 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.022s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6790,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.388748 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:35.573356 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.184s	user 0.126s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":687,"lbm_read_time_us":11030,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31400,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:35.573982 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=18.063937
I20260812 06:18:35.648268 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.074s	user 0.041s	sys 0.029s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":35088,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.648954 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:35.662230 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.662825 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:35.883430 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.220s	user 0.133s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":14771,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35031,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":3000}
I20260812 06:18:35.884136 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=18.063937
I20260812 06:18:35.956817 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.072s	user 0.021s	sys 0.043s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30914,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.957396 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:35.968284 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.969133 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:36.181867 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.212s	user 0.127s	sys 0.085s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":14360,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35664,"lbm_writes_lt_1ms":643,"mutex_wait_us":321,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":3000}
I20260812 06:18:36.182652 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:36.226845 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.044s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19203,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.227437 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:36.250296 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.023s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.250784 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:36.426661 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.176s	user 0.116s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":601,"lbm_read_time_us":10338,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30248,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:18:36.427727 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=15.087375
I20260812 06:18:36.476198 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.048s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16615023,"delete_count":0,"lbm_write_time_us":21292,"lbm_writes_lt_1ms":408,"reinsert_count":0,"update_count":2025}
I20260812 06:18:36.477044 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:36.491910 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5485,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:36.492511 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:36.524109 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1759,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1559,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:36.525089 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): free 117302571 bytes of WAL
I20260812 06:18:36.525431 15082 log_reader.cc:385] T cbb963b3a75b4b74a98eed8a6bfc530d: removed 12 log segments from log reader
I20260812 06:18:36.525504 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000015 (ops 69-73)
I20260812 06:18:36.525561 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000016 (ops 74-78)
I20260812 06:18:36.525628 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000017 (ops 79-82)
I20260812 06:18:36.525667 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000018 (ops 83-87)
I20260812 06:18:36.525704 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000019 (ops 88-92)
I20260812 06:18:36.525743 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000020 (ops 93-97)
I20260812 06:18:36.525779 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000021 (ops 98-102)
I20260812 06:18:36.525818 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000022 (ops 103-107)
I20260812 06:18:36.525856 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000023 (ops 108-112)
I20260812 06:18:36.525892 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000024 (ops 113-116)
I20260812 06:18:36.525929 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000025 (ops 117-121)
I20260812 06:18:36.525966 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000026 (ops 122-126)
I20260812 06:18:36.553747 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:36.554311 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=3.181125
I20260812 06:18:36.567243 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4964173,"delete_count":0,"lbm_write_time_us":5165,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:18:36.567795 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): 472 bytes on disk
I20260812 06:18:36.568243 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.568746 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:36.578771 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3245,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:36.579283 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): free 11564891 bytes of WAL
I20260812 06:18:36.579521 15082 log_reader.cc:385] T cbb963b3a75b4b74a98eed8a6bfc530d: removed 1 log segments from log reader
I20260812 06:18:36.579587 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000027 (ops 127-130)
I20260812 06:18:36.582154 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:36.582646 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:36.816130 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.233s	user 0.147s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":960,"lbm_read_time_us":16739,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38340,"lbm_writes_lt_1ms":743,"mutex_wait_us":329,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17280,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:36.816722 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=18.063937
I20260812 06:18:36.874358 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.057s	user 0.032s	sys 0.024s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25642,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.874902 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:36.891929 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.892455 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:37.051915 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.159s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":10834,"lbm_reads_lt_1ms":668,"lbm_write_time_us":32592,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26752,"update_count":3000}
I20260812 06:18:37.052621 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:37.105988 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.053s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21029,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.106591 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:37.120221 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.120791 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:37.295991 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.175s	user 0.127s	sys 0.041s 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":81,"lbm_read_time_us":13458,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32377,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:37.296802 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:37.349465 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.052s	user 0.026s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23447,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.350075 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:37.499779 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.149s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":452,"lbm_read_time_us":9135,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23268,"lbm_writes_lt_1ms":443,"mutex_wait_us":128,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:18:37.500416 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:37.553537 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.053s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.554097 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:37.565752 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.566248 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:37.757105 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.191s	user 0.132s	sys 0.049s 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":201,"lbm_read_time_us":12013,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31457,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:37.757975 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:37.810779 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.053s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21951,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.811309 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:37.823916 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.824704 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:37.997799 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.173s	user 0.147s	sys 0.020s 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":192,"lbm_read_time_us":10459,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31797,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:18:37.998626 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:38.054376 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.056s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21962,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.055011 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=2.188937
I20260812 06:18:38.067468 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.068185 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:38.101743 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushMRSOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1467,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1897,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":4864}
I20260812 06:18:38.102540 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): free 120553646 bytes of WAL
I20260812 06:18:38.102795 15082 log_reader.cc:385] T cbb963b3a75b4b74a98eed8a6bfc530d: removed 12 log segments from log reader
I20260812 06:18:38.102872 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000028 (ops 131-135)
I20260812 06:18:38.102923 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000029 (ops 136-140)
I20260812 06:18:38.102981 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000030 (ops 141-145)
I20260812 06:18:38.103026 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000031 (ops 146-150)
I20260812 06:18:38.103067 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000032 (ops 151-154)
I20260812 06:18:38.103106 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000033 (ops 155-159)
I20260812 06:18:38.103154 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000034 (ops 160-164)
I20260812 06:18:38.103195 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000035 (ops 165-169)
I20260812 06:18:38.103235 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000036 (ops 170-174)
I20260812 06:18:38.103273 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000037 (ops 175-179)
I20260812 06:18:38.103312 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000038 (ops 180-184)
I20260812 06:18:38.103351 15082 log.cc:1079] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: Deleting log segment in path: /tmp/dist-test-task8pEPTz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507423280-14637-0/minicluster-data/ts-0-root/wals/cbb963b3a75b4b74a98eed8a6bfc530d/wal-000000039 (ops 185-188)
I20260812 06:18:38.131673 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: LogGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.029s	user 0.002s	sys 0.024s Metrics: {}
I20260812 06:18:38.132266 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d): 483 bytes on disk
I20260812 06:18:38.132917 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: UndoDeltaBlockGCOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.133589 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=3.181125
I20260812 06:18:38.162765 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.029s	user 0.013s	sys 0.014s Metrics: {"bytes_written":5251341,"delete_count":0,"lbm_write_time_us":7387,"lbm_writes_lt_1ms":131,"mutex_wait_us":85,"reinsert_count":0,"update_count":640}
I20260812 06:18:38.163401 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.196750
I20260812 06:18:38.172013 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.008s	user 0.000s	sys 0.007s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3157,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:38.172521 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:38.387714 14637 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.968s	user 1.846s	sys 0.134s
I20260812 06:18:38.410277 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.238s	user 0.148s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16771,"lbm_reads_lt_1ms":770,"lbm_write_time_us":41637,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":3500}
I20260812 06:18:38.410790 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=14.095187
I20260812 06:18:38.443079 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: FlushDeltaMemStoresOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.032s	user 0.024s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15390,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:38.443650 15184 maintenance_manager.cc:419] P 756d9b976cdd4630b215a439973d0d3d: Scheduling MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d): perf score=1.000000
I20260812 06:18:38.471331 14637 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.083s	user 0.001s	sys 0.000s
I20260812 06:18:38.471873 14637 tablet_server.cc:179] TabletServer@127.14.75.65:0 shutting down...
I20260812 06:18:38.598728 15082 maintenance_manager.cc:643] P 756d9b976cdd4630b215a439973d0d3d: MajorDeltaCompactionOp(cbb963b3a75b4b74a98eed8a6bfc530d) complete. Timing: real 0.155s	user 0.125s	sys 0.027s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1090,"lbm_read_time_us":11415,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22788,"lbm_writes_lt_1ms":443,"mutex_wait_us":378,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":49408,"update_count":2000}
I20260812 06:18:38.599385 14637 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.599622 14637 tablet_replica.cc:333] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d: stopping tablet replica
I20260812 06:18:38.599792 14637 raft_consensus.cc:2243] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.599994 14637 raft_consensus.cc:2272] T cbb963b3a75b4b74a98eed8a6bfc530d P 756d9b976cdd4630b215a439973d0d3d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.615468 14637 tablet_server.cc:196] TabletServer@127.14.75.65:0 shutdown complete.
I20260812 06:18:38.637645 14637 master.cc:562] Master@127.14.75.126:34983 shutting down...
I20260812 06:18:38.641608 14637 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.641817 14637 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.641916 14637 tablet_replica.cc:333] T 00000000000000000000000000000000 P ad3eb555b78c4e1a9a7cb75d0a1e0d99: stopping tablet replica
I20260812 06:18:38.654659 14637 master.cc:584] Master@127.14.75.126:34983 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5535 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11304 ms total)

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