[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:10.335196 17480 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.18.62:37615
I20260812 06:17:10.336186 17480 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:10.336748 17480 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:10.343694 17480 server_base.cc:1061] running on GCE node
W20260812 06:17:10.343786 17490 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.343897 17488 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.344062 17495 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.344569 17480 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.344703 17480 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:10.344799 17480 hybrid_clock.cc:648] HybridClock initialized: now 1786515430344796 us; error 0 us; skew 500 ppm
I20260812 06:17:10.346712 17480 webserver.cc:533] Webserver started at http://127.17.18.62:38577/ using document root <none> and password file <none>
I20260812 06:17:10.347266 17480 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.347328 17480 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.347515 17480 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.349206 17480 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/master-0-root/instance:
uuid: "677fe550da814713beec86adb10429c7"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-g170"
I20260812 06:17:10.352685 17480 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:10.354858 17505 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.355909 17480 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:10.356048 17480 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/master-0-root
uuid: "677fe550da814713beec86adb10429c7"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-g170"
I20260812 06:17:10.356149 17480 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:10.384532 17480 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.385150 17480 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:10.385350 17480 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.392836 17480 rpc_server.cc:307] RPC server started. Bound to: 127.17.18.62:37615
I20260812 06:17:10.392843 17585 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.18.62:37615 every 8 connection(s)
I20260812 06:17:10.395002 17586 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.400146 17586 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: Bootstrap starting.
I20260812 06:17:10.402482 17586 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.403357 17586 log.cc:826] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:10.405001 17586 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: No bootstrap required, opened a new log
I20260812 06:17:10.407661 17586 raft_consensus.cc:359] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "677fe550da814713beec86adb10429c7" member_type: VOTER }
I20260812 06:17:10.407819 17586 raft_consensus.cc:385] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.407928 17586 raft_consensus.cc:740] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 677fe550da814713beec86adb10429c7, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.408509 17586 consensus_queue.cc:260] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [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: "677fe550da814713beec86adb10429c7" member_type: VOTER }
I20260812 06:17:10.408685 17586 raft_consensus.cc:399] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.408756 17586 raft_consensus.cc:493] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.408908 17586 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.409593 17586 raft_consensus.cc:515] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "677fe550da814713beec86adb10429c7" member_type: VOTER }
I20260812 06:17:10.409965 17586 leader_election.cc:304] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [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: 677fe550da814713beec86adb10429c7; no voters: 
I20260812 06:17:10.410205 17586 leader_election.cc:290] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.410333 17593 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.410596 17593 raft_consensus.cc:697] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 1 LEADER]: Becoming Leader. State: Replica: 677fe550da814713beec86adb10429c7, State: Running, Role: LEADER
I20260812 06:17:10.411038 17593 consensus_queue.cc:237] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [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: "677fe550da814713beec86adb10429c7" member_type: VOTER }
I20260812 06:17:10.411275 17586 sys_catalog.cc:565] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:10.412724 17596 sys_catalog.cc:455] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 677fe550da814713beec86adb10429c7. Latest consensus state: current_term: 1 leader_uuid: "677fe550da814713beec86adb10429c7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "677fe550da814713beec86adb10429c7" member_type: VOTER } }
I20260812 06:17:10.412891 17596 sys_catalog.cc:458] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.412964 17595 sys_catalog.cc:455] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "677fe550da814713beec86adb10429c7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "677fe550da814713beec86adb10429c7" member_type: VOTER } }
I20260812 06:17:10.413034 17595 sys_catalog.cc:458] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.413570 17480 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:10.416059 17620 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:10.416133 17620 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:10.416195 17609 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:10.417093 17609 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:10.421770 17609 catalog_manager.cc:1383] Generated new cluster ID: 417a1417194440099f80481df5f06cca
I20260812 06:17:10.421845 17609 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:10.433563 17609 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:10.434377 17609 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:10.444198 17609 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: Generated new TSK 0
I20260812 06:17:10.444943 17609 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:10.446553 17480 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:10.449479 17627 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.449470 17628 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.449584 17631 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.449855 17480 server_base.cc:1061] running on GCE node
I20260812 06:17:10.450034 17480 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.450095 17480 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:10.450139 17480 hybrid_clock.cc:648] HybridClock initialized: now 1786515430450138 us; error 0 us; skew 500 ppm
I20260812 06:17:10.451114 17480 webserver.cc:533] Webserver started at http://127.17.18.1:40153/ using document root <none> and password file <none>
I20260812 06:17:10.451311 17480 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.451385 17480 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.451467 17480 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.451879 17480 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/instance:
uuid: "9454e8ed593d45318c8cdc44ecaa5436"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-g170"
I20260812 06:17:10.453541 17480 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:10.454582 17640 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.454869 17480 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:10.454938 17480 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root
uuid: "9454e8ed593d45318c8cdc44ecaa5436"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-g170"
I20260812 06:17:10.455022 17480 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:10.460987 17480 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.461381 17480 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.461866 17480 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:10.462723 17480 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:10.462774 17480 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.462834 17480 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:10.462878 17480 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.469908 17480 rpc_server.cc:307] RPC server started. Bound to: 127.17.18.1:45295
I20260812 06:17:10.469939 17751 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.18.1:45295 every 8 connection(s)
I20260812 06:17:10.483121 17752 heartbeater.cc:344] Connected to a master server at 127.17.18.62:37615
I20260812 06:17:10.483392 17752 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:10.483927 17752 heartbeater.cc:507] Master 127.17.18.62:37615 requested a full tablet report, sending...
I20260812 06:17:10.485539 17529 ts_manager.cc:194] Registered new tserver with Master: 9454e8ed593d45318c8cdc44ecaa5436 (127.17.18.1:45295)
I20260812 06:17:10.486285 17480 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015753226s
I20260812 06:17:10.487033 17529 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44972
I20260812 06:17:10.496317 17529 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44978:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:10.511940 17689 tablet_service.cc:1511] Processing CreateTablet for tablet c0ac0b1bc3a04e869f4913499e5d81c2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=740a383bd32544bb9ab79c95ec25f0e6]), partition=
I20260812 06:17:10.512435 17689 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c0ac0b1bc3a04e869f4913499e5d81c2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.514865 17776 tablet_bootstrap.cc:492] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Bootstrap starting.
I20260812 06:17:10.516275 17776 tablet_bootstrap.cc:654] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.517699 17776 tablet_bootstrap.cc:492] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: No bootstrap required, opened a new log
I20260812 06:17:10.517813 17776 ts_tablet_manager.cc:1403] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:10.518316 17776 raft_consensus.cc:359] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9454e8ed593d45318c8cdc44ecaa5436" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45295 } }
I20260812 06:17:10.518460 17776 raft_consensus.cc:385] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.518498 17776 raft_consensus.cc:740] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9454e8ed593d45318c8cdc44ecaa5436, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.518644 17776 consensus_queue.cc:260] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [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: "9454e8ed593d45318c8cdc44ecaa5436" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45295 } }
I20260812 06:17:10.518750 17776 raft_consensus.cc:399] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.518793 17776 raft_consensus.cc:493] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.518849 17776 raft_consensus.cc:3060] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.519840 17776 raft_consensus.cc:515] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9454e8ed593d45318c8cdc44ecaa5436" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45295 } }
I20260812 06:17:10.519992 17776 leader_election.cc:304] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [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: 9454e8ed593d45318c8cdc44ecaa5436; no voters: 
I20260812 06:17:10.520208 17776 leader_election.cc:290] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.520366 17778 raft_consensus.cc:2804] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.520609 17776 ts_tablet_manager.cc:1434] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:10.520637 17778 raft_consensus.cc:697] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 1 LEADER]: Becoming Leader. State: Replica: 9454e8ed593d45318c8cdc44ecaa5436, State: Running, Role: LEADER
I20260812 06:17:10.520854 17778 consensus_queue.cc:237] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [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: "9454e8ed593d45318c8cdc44ecaa5436" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45295 } }
I20260812 06:17:10.520988 17752 heartbeater.cc:499] Master 127.17.18.62:37615 was elected leader, sending a full tablet report...
I20260812 06:17:10.523625 17529 catalog_manager.cc:5719] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9454e8ed593d45318c8cdc44ecaa5436 (127.17.18.1). New cstate: current_term: 1 leader_uuid: "9454e8ed593d45318c8cdc44ecaa5436" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9454e8ed593d45318c8cdc44ecaa5436" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45295 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:10.598074 17480 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.026s	sys 0.008s
I20260812 06:17:10.721378 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=15.086190
I20260812 06:17:10.858958 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.137s	user 0.119s	sys 0.016s Metrics: {"bytes_written":8943513,"cfile_init":1,"compiler_manager_pool.queue_time_us":91,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":296,"dirs.run_wall_time_us":887,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33919,"lbm_writes_lt_1ms":575,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":80640,"update_count":1090}
I20260812 06:17:10.860009 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): free 11976772 bytes of WAL
I20260812 06:17:10.860416 17650 log_reader.cc:385] T c0ac0b1bc3a04e869f4913499e5d81c2: removed 1 log segments from log reader
I20260812 06:17:10.860494 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000001 (ops 1-6)
I20260812 06:17:10.863615 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:10.864074 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:10.879773 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:17:10.880218 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:11.014770 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.134s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528881,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":6815,"lbm_reads_lt_1ms":364,"lbm_write_time_us":24538,"lbm_writes_lt_1ms":343,"mutex_wait_us":40,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":356,"threads_started":5,"update_count":1500}
I20260812 06:17:11.015513 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): 12308958 bytes on disk
I20260812 06:17:11.016089 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.016661 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:11.060986 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.044s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15927,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.061419 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:11.071606 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.072082 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:11.194563 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.122s	user 0.104s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":8437,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23756,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:17:11.195179 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:11.241468 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.046s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17374,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.241977 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:11.367331 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.125s	user 0.085s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1265,"lbm_read_time_us":9531,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18519,"lbm_writes_lt_1ms":343,"mutex_wait_us":294,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":1500}
I20260812 06:17:11.367833 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:11.405870 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.038s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13723,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.406440 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:11.555148 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.149s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1092,"lbm_read_time_us":6900,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24383,"lbm_writes_lt_1ms":343,"mutex_wait_us":358,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:11.555945 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:11.595752 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.040s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16378,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.596254 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:11.726395 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.130s	user 0.085s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":245,"lbm_read_time_us":8719,"lbm_reads_lt_1ms":367,"lbm_write_time_us":23087,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":1500}
I20260812 06:17:11.727041 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:11.762169 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.035s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14053,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.762734 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:11.872043 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.109s	user 0.081s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528783,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":195,"lbm_read_time_us":6810,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21358,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.872756 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:11.914753 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.042s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16414,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.915337 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:11.926379 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.926975 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:12.051721 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.124s	user 0.103s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":524,"lbm_read_time_us":9228,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23924,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:12.052356 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:12.105003 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.052s	user 0.019s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16607,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.105590 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:12.116614 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.117269 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:12.276083 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.158s	user 0.112s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1028,"lbm_read_time_us":11563,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24981,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:12.276822 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:12.326925 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.050s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18011,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.327482 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:12.339111 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.339660 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:12.371636 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1368,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1759,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:12.372618 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): free 129320489 bytes of WAL
I20260812 06:17:12.372931 17650 log_reader.cc:385] T c0ac0b1bc3a04e869f4913499e5d81c2: removed 13 log segments from log reader
I20260812 06:17:12.373003 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000002 (ops 7-11)
I20260812 06:17:12.373056 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000003 (ops 12-16)
I20260812 06:17:12.373111 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000004 (ops 17-20)
I20260812 06:17:12.373153 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000005 (ops 21-25)
I20260812 06:17:12.373193 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000006 (ops 26-30)
I20260812 06:17:12.373241 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000007 (ops 31-35)
I20260812 06:17:12.373281 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000008 (ops 36-40)
I20260812 06:17:12.373320 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000009 (ops 41-44)
I20260812 06:17:12.373361 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000010 (ops 45-49)
I20260812 06:17:12.373401 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000011 (ops 50-54)
I20260812 06:17:12.373440 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000012 (ops 55-59)
I20260812 06:17:12.373477 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000013 (ops 60-64)
I20260812 06:17:12.373517 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000014 (ops 65-69)
I20260812 06:17:12.404156 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:17:12.404671 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): 482 bytes on disk
I20260812 06:17:12.405233 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.405795 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=4.173312
I20260812 06:17:12.420958 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":6235918,"delete_count":0,"lbm_write_time_us":6218,"lbm_writes_lt_1ms":155,"reinsert_count":0,"update_count":760}
I20260812 06:17:12.421423 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:12.430173 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":1969352,"delete_count":0,"lbm_write_time_us":3218,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:17:12.430593 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:12.626252 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.195s	user 0.141s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1436,"lbm_read_time_us":13532,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33276,"lbm_writes_lt_1ms":643,"mutex_wait_us":377,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":61824,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:12.626844 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=14.095187
I20260812 06:17:12.679426 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.052s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.679977 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:12.701607 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.021s	user 0.002s	sys 0.019s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.702147 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:12.874511 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.172s	user 0.097s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1103,"lbm_read_time_us":12151,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31119,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:17:12.875339 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=11.118625
I20260812 06:17:12.910933 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.035s	user 0.015s	sys 0.018s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15845,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.911525 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:12.931342 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5680,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.931970 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:13.052567 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.120s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":7902,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26296,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:13.053180 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:13.098801 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.045s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16253,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.099273 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.109414 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.109833 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:13.238260 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.128s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1042,"lbm_read_time_us":9869,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25682,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:17:13.238994 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:13.287077 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.048s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15564,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":1500}
I20260812 06:17:13.287714 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.298441 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.298882 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:13.422883 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.124s	user 0.111s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1104,"lbm_read_time_us":9346,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25076,"lbm_writes_lt_1ms":443,"mutex_wait_us":369,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":43264,"update_count":2000}
I20260812 06:17:13.423445 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:13.478768 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.055s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15903,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.479276 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.491150 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.491618 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:13.642778 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.151s	user 0.115s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":751,"lbm_read_time_us":12457,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25812,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:17:13.643502 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:13.675674 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.032s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14041,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.676209 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.690722 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.692018 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:13.826515 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.134s	user 0.099s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":10097,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26699,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:13.827396 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:13.871387 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.044s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18661,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.871909 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.882678 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.883249 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:13.915064 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.032s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1186,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1803,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:13.915978 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): free 133024342 bytes of WAL
I20260812 06:17:13.916273 17650 log_reader.cc:385] T c0ac0b1bc3a04e869f4913499e5d81c2: removed 13 log segments from log reader
I20260812 06:17:13.916347 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000015 (ops 70-74)
I20260812 06:17:13.916394 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000016 (ops 75-79)
I20260812 06:17:13.916417 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000017 (ops 80-84)
I20260812 06:17:13.916440 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000018 (ops 85-89)
I20260812 06:17:13.916461 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000019 (ops 90-94)
I20260812 06:17:13.916488 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000020 (ops 95-99)
I20260812 06:17:13.916513 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000021 (ops 100-104)
I20260812 06:17:13.916536 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000022 (ops 105-109)
I20260812 06:17:13.916567 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000023 (ops 110-114)
I20260812 06:17:13.916594 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000024 (ops 115-119)
I20260812 06:17:13.916618 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000025 (ops 120-124)
I20260812 06:17:13.916646 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000026 (ops 125-128)
I20260812 06:17:13.916730 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000027 (ops 129-133)
I20260812 06:17:13.951445 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.035s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:17:13.952000 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.969250 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.969683 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): 482 bytes on disk
I20260812 06:17:13.970109 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.970592 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:13.980986 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.981611 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:14.167332 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.185s	user 0.151s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836374,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":7809,"lbm_read_time_us":13883,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35127,"lbm_writes_lt_1ms":643,"mutex_wait_us":2634,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":109,"threads_started":1,"update_count":3000}
I20260812 06:17:14.168111 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=14.095187
I20260812 06:17:14.223124 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.055s	user 0.040s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.223656 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:14.237437 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.238185 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:14.408604 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.170s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":11584,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32221,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:17:14.409296 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=14.095187
I20260812 06:17:14.464449 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.055s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21494,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.465220 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:14.476281 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.476832 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:14.640197 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.163s	user 0.122s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":11117,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31642,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:14.640894 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:14.682293 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.041s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18541,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.683212 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:14.695046 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.695499 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:14.858747 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.163s	user 0.110s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":11749,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27653,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:14.859445 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=14.095187
I20260812 06:17:14.927706 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.068s	user 0.035s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23725,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.928388 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:14.939316 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.939821 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:15.120673 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.181s	user 0.105s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":13119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31966,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:15.121479 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:15.161038 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.039s	user 0.036s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17511,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.161760 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:15.178081 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.178540 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:15.310978 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.132s	user 0.099s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":10171,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26594,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:17:15.311513 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=10.126437
I20260812 06:17:15.355751 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.044s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15922,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.356299 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:15.369478 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.370280 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:15.403030 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushMRSOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.033s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":1677,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2256,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:15.403895 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): free 112239554 bytes of WAL
I20260812 06:17:15.404183 17650 log_reader.cc:385] T c0ac0b1bc3a04e869f4913499e5d81c2: removed 11 log segments from log reader
I20260812 06:17:15.404235 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000028 (ops 134-138)
I20260812 06:17:15.404268 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000029 (ops 139-143)
I20260812 06:17:15.404333 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000030 (ops 144-148)
I20260812 06:17:15.404398 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000031 (ops 149-153)
I20260812 06:17:15.404441 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000032 (ops 154-158)
I20260812 06:17:15.404502 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000033 (ops 159-162)
I20260812 06:17:15.404542 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000034 (ops 163-167)
I20260812 06:17:15.404582 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000035 (ops 168-172)
I20260812 06:17:15.404623 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000036 (ops 173-177)
I20260812 06:17:15.404661 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000037 (ops 178-182)
I20260812 06:17:15.404711 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000038 (ops 183-187)
I20260812 06:17:15.430735 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:15.431301 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): 462 bytes on disk
I20260812 06:17:15.431885 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: UndoDeltaBlockGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.432647 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=3.181125
I20260812 06:17:15.444905 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4853,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.445425 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2): free 12018004 bytes of WAL
I20260812 06:17:15.445655 17650 log_reader.cc:385] T c0ac0b1bc3a04e869f4913499e5d81c2: removed 1 log segments from log reader
I20260812 06:17:15.445725 17650 log.cc:1079] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/c0ac0b1bc3a04e869f4913499e5d81c2/wal-000000039 (ops 188-192)
I20260812 06:17:15.448125 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: LogGCOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:15.448490 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=2.188937
I20260812 06:17:15.460122 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.460660 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=1.000000
I20260812 06:17:15.621701 17480 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.024s	user 1.885s	sys 0.140s
I20260812 06:17:15.624188 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: MajorDeltaCompactionOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.163s	user 0.107s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":783,"lbm_read_time_us":10982,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34987,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27776,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:17:15.626024 17753 maintenance_manager.cc:419] P 9454e8ed593d45318c8cdc44ecaa5436: Scheduling FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2): perf score=14.095187
I20260812 06:17:15.652542 17480 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.001s	sys 0.000s
I20260812 06:17:15.653256 17480 tablet_server.cc:179] TabletServer@127.17.18.1:0 shutting down...
I20260812 06:17:15.671914 17650 maintenance_manager.cc:643] P 9454e8ed593d45318c8cdc44ecaa5436: FlushDeltaMemStoresOp(c0ac0b1bc3a04e869f4913499e5d81c2) complete. Timing: real 0.046s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20217,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.672648 17480 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:15.673198 17480 tablet_replica.cc:333] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436: stopping tablet replica
I20260812 06:17:15.673401 17480 raft_consensus.cc:2243] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.673591 17480 raft_consensus.cc:2272] T c0ac0b1bc3a04e869f4913499e5d81c2 P 9454e8ed593d45318c8cdc44ecaa5436 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.688484 17480 tablet_server.cc:196] TabletServer@127.17.18.1:0 shutdown complete.
I20260812 06:17:15.693382 17480 master.cc:562] Master@127.17.18.62:37615 shutting down...
I20260812 06:17:15.697562 17480 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.697755 17480 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.697854 17480 tablet_replica.cc:333] T 00000000000000000000000000000000 P 677fe550da814713beec86adb10429c7: stopping tablet replica
I20260812 06:17:15.710258 17480 master.cc:584] Master@127.17.18.62:37615 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5470 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:15.821095 17480 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.18.62:42649
I20260812 06:17:15.821614 17480 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.824163 17808 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.824402 17480 server_base.cc:1061] running on GCE node
W20260812 06:17:15.824402 17807 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:15.824519 17810 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.824931 17480 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.824985 17480 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:15.825003 17480 hybrid_clock.cc:648] HybridClock initialized: now 1786515435825004 us; error 0 us; skew 500 ppm
I20260812 06:17:15.825971 17480 webserver.cc:533] Webserver started at http://127.17.18.62:45069/ using document root <none> and password file <none>
I20260812 06:17:15.826124 17480 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.826169 17480 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.826226 17480 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.826581 17480 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/master-0-root/instance:
uuid: "87752c5846984833a7e92323182febe2"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-g170"
I20260812 06:17:15.828236 17480 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:15.829596 17826 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.829981 17480 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:15.830052 17480 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/master-0-root
uuid: "87752c5846984833a7e92323182febe2"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-g170"
I20260812 06:17:15.830119 17480 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:15.841140 17480 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.841612 17480 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.845752 17480 rpc_server.cc:307] RPC server started. Bound to: 127.17.18.62:42649
I20260812 06:17:15.845824 17921 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.18.62:42649 every 8 connection(s)
I20260812 06:17:15.846827 17923 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:15.848899 17923 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2: Bootstrap starting.
I20260812 06:17:15.849699 17923 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.850798 17923 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2: No bootstrap required, opened a new log
I20260812 06:17:15.851496 17923 raft_consensus.cc:359] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87752c5846984833a7e92323182febe2" member_type: VOTER }
I20260812 06:17:15.851676 17923 raft_consensus.cc:385] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.851774 17923 raft_consensus.cc:740] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 87752c5846984833a7e92323182febe2, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.852005 17923 consensus_queue.cc:260] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [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: "87752c5846984833a7e92323182febe2" member_type: VOTER }
I20260812 06:17:15.852136 17923 raft_consensus.cc:399] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.852208 17923 raft_consensus.cc:493] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.852269 17923 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.853137 17923 raft_consensus.cc:515] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87752c5846984833a7e92323182febe2" member_type: VOTER }
I20260812 06:17:15.853313 17923 leader_election.cc:304] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [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: 87752c5846984833a7e92323182febe2; no voters: 
I20260812 06:17:15.853538 17923 leader_election.cc:290] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.853758 17929 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.854001 17929 raft_consensus.cc:697] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 1 LEADER]: Becoming Leader. State: Replica: 87752c5846984833a7e92323182febe2, State: Running, Role: LEADER
I20260812 06:17:15.854084 17923 sys_catalog.cc:565] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:15.854183 17929 consensus_queue.cc:237] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [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: "87752c5846984833a7e92323182febe2" member_type: VOTER }
I20260812 06:17:15.854717 17936 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 87752c5846984833a7e92323182febe2. Latest consensus state: current_term: 1 leader_uuid: "87752c5846984833a7e92323182febe2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87752c5846984833a7e92323182febe2" member_type: VOTER } }
I20260812 06:17:15.854704 17931 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "87752c5846984833a7e92323182febe2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87752c5846984833a7e92323182febe2" member_type: VOTER } }
I20260812 06:17:15.854835 17936 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.854843 17931 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.855551 17943 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:15.856603 17943 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:15.856871 17480 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:15.858775 17943 catalog_manager.cc:1383] Generated new cluster ID: 1a10418ed8d64fef816eb31f3ae9da58
I20260812 06:17:15.858842 17943 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:15.868583 17943 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:15.869283 17943 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:15.878001 17943 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2: Generated new TSK 0
I20260812 06:17:15.878252 17943 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:15.889925 17480 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.892072 17967 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:15.892207 17968 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:15.892448 17970 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.892805 17480 server_base.cc:1061] running on GCE node
I20260812 06:17:15.893019 17480 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.893065 17480 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:15.893106 17480 hybrid_clock.cc:648] HybridClock initialized: now 1786515435893105 us; error 0 us; skew 500 ppm
I20260812 06:17:15.894040 17480 webserver.cc:533] Webserver started at http://127.17.18.1:35613/ using document root <none> and password file <none>
I20260812 06:17:15.894268 17480 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.894328 17480 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.894457 17480 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.894994 17480 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/instance:
uuid: "2b30bded7b5947ff84268495806e3ecf"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-g170"
I20260812 06:17:15.896718 17480 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:15.897884 17978 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.898211 17480 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:15.898283 17480 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root
uuid: "2b30bded7b5947ff84268495806e3ecf"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-g170"
I20260812 06:17:15.898406 17480 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:15.909391 17480 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.909834 17480 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.910168 17480 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:15.910703 17480 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:15.910744 17480 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.910813 17480 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:15.910861 17480 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.916102 17480 rpc_server.cc:307] RPC server started. Bound to: 127.17.18.1:45181
I20260812 06:17:15.916246 18074 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.18.1:45181 every 8 connection(s)
I20260812 06:17:15.928754 18075 heartbeater.cc:344] Connected to a master server at 127.17.18.62:42649
I20260812 06:17:15.928941 18075 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:15.929234 18075 heartbeater.cc:507] Master 127.17.18.62:42649 requested a full tablet report, sending...
I20260812 06:17:15.930039 17861 ts_manager.cc:194] Registered new tserver with Master: 2b30bded7b5947ff84268495806e3ecf (127.17.18.1:45181)
I20260812 06:17:15.930233 17480 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013571791s
I20260812 06:17:15.930848 17861 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52110
I20260812 06:17:15.939608 17861 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52124:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:15.949259 18018 tablet_service.cc:1511] Processing CreateTablet for tablet 1a530db31e7c4419b0cb6062c35f7615 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c5fe56dd293a44aeb578fcde2c12b4e8]), partition=
I20260812 06:17:15.949519 18018 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1a530db31e7c4419b0cb6062c35f7615. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:15.951442 18096 tablet_bootstrap.cc:492] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Bootstrap starting.
I20260812 06:17:15.952307 18096 tablet_bootstrap.cc:654] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.953426 18096 tablet_bootstrap.cc:492] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: No bootstrap required, opened a new log
I20260812 06:17:15.953503 18096 ts_tablet_manager.cc:1403] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:17:15.953871 18096 raft_consensus.cc:359] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2b30bded7b5947ff84268495806e3ecf" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45181 } }
I20260812 06:17:15.953958 18096 raft_consensus.cc:385] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.953979 18096 raft_consensus.cc:740] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2b30bded7b5947ff84268495806e3ecf, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.954123 18096 consensus_queue.cc:260] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [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: "2b30bded7b5947ff84268495806e3ecf" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45181 } }
I20260812 06:17:15.954206 18096 raft_consensus.cc:399] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.954250 18096 raft_consensus.cc:493] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.954304 18096 raft_consensus.cc:3060] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.955200 18096 raft_consensus.cc:515] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2b30bded7b5947ff84268495806e3ecf" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45181 } }
I20260812 06:17:15.955397 18096 leader_election.cc:304] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [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: 2b30bded7b5947ff84268495806e3ecf; no voters: 
I20260812 06:17:15.955628 18096 leader_election.cc:290] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.955788 18099 raft_consensus.cc:2804] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.955972 18075 heartbeater.cc:499] Master 127.17.18.62:42649 was elected leader, sending a full tablet report...
I20260812 06:17:15.956043 18096 ts_tablet_manager.cc:1434] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:15.956053 18099 raft_consensus.cc:697] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 1 LEADER]: Becoming Leader. State: Replica: 2b30bded7b5947ff84268495806e3ecf, State: Running, Role: LEADER
I20260812 06:17:15.956254 18099 consensus_queue.cc:237] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [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: "2b30bded7b5947ff84268495806e3ecf" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45181 } }
I20260812 06:17:15.957784 17861 catalog_manager.cc:5719] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf reported cstate change: term changed from 0 to 1, leader changed from <none> to 2b30bded7b5947ff84268495806e3ecf (127.17.18.1). New cstate: current_term: 1 leader_uuid: "2b30bded7b5947ff84268495806e3ecf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2b30bded7b5947ff84268495806e3ecf" member_type: VOTER last_known_addr { host: "127.17.18.1" port: 45181 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:16.024382 17480 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.022s	sys 0.004s
I20260812 06:17:16.167145 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615): perf score=19.054940
I20260812 06:17:16.343113 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.176s	user 0.125s	sys 0.048s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1132,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48133,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:16.343840 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling LogGCOp(1a530db31e7c4419b0cb6062c35f7615): free 20743880 bytes of WAL
I20260812 06:17:16.344128 17988 log_reader.cc:385] T 1a530db31e7c4419b0cb6062c35f7615: removed 2 log segments from log reader
I20260812 06:17:16.344187 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000001 (ops 1-6)
I20260812 06:17:16.344226 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000002 (ops 7-11)
I20260812 06:17:16.350769 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: LogGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:16.351348 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615): 16411393 bytes on disk
I20260812 06:17:16.351895 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.352365 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:16.387880 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.035s	user 0.017s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.388430 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:16.400681 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.401307 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:16.599483 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.198s	user 0.111s	sys 0.083s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":574,"lbm_read_time_us":14496,"lbm_reads_lt_1ms":569,"lbm_write_time_us":32612,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":320,"threads_started":5,"update_count":2500}
I20260812 06:17:16.600296 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:16.656623 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.056s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22774,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.657167 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:16.669189 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.669759 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:16.878621 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.209s	user 0.117s	sys 0.085s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1389,"lbm_read_time_us":13619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32318,"lbm_writes_lt_1ms":543,"mutex_wait_us":365,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:17:16.879475 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:16.938788 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.059s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26091,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.939324 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:16.964259 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.025s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.964735 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:16.988880 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.024s	user 0.009s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.989498 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:17.217078 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.227s	user 0.145s	sys 0.074s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":823,"lbm_read_time_us":15071,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36739,"lbm_writes_lt_1ms":643,"mutex_wait_us":405,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:17:17.217837 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:17.289697 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.072s	user 0.047s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28126,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:17.290305 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:17.302695 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.303539 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:17.536633 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.233s	user 0.164s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":18279,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38882,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":3000}
I20260812 06:17:17.537211 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:17.596462 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.059s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20977,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.597209 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:17.616956 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.020s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.617465 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:17.654677 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.037s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1508,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1596,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:17.655411 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling LogGCOp(1a530db31e7c4419b0cb6062c35f7615): free 103925190 bytes of WAL
I20260812 06:17:17.655653 17988 log_reader.cc:385] T 1a530db31e7c4419b0cb6062c35f7615: removed 10 log segments from log reader
I20260812 06:17:17.655694 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000003 (ops 12-16)
I20260812 06:17:17.655725 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000004 (ops 17-21)
I20260812 06:17:17.655789 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000005 (ops 22-26)
I20260812 06:17:17.655824 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000006 (ops 27-31)
I20260812 06:17:17.655859 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000007 (ops 32-36)
I20260812 06:17:17.655903 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000008 (ops 37-41)
I20260812 06:17:17.655943 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000009 (ops 42-46)
I20260812 06:17:17.655984 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000010 (ops 47-51)
I20260812 06:17:17.656020 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000011 (ops 52-56)
I20260812 06:17:17.656059 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000012 (ops 57-61)
I20260812 06:17:17.681685 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: LogGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:17.682113 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615): 447 bytes on disk
I20260812 06:17:17.682729 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.683195 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=6.157687
I20260812 06:17:17.704560 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.021s	user 0.015s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8892,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:17.705037 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling LogGCOp(1a530db31e7c4419b0cb6062c35f7615): free 12017983 bytes of WAL
I20260812 06:17:17.705281 17988 log_reader.cc:385] T 1a530db31e7c4419b0cb6062c35f7615: removed 1 log segments from log reader
I20260812 06:17:17.705340 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000013 (ops 62-66)
I20260812 06:17:17.708724 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: LogGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:17.709259 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:17.943719 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.234s	user 0.132s	sys 0.100s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":4054,"lbm_read_time_us":16481,"lbm_reads_lt_1ms":765,"lbm_write_time_us":41093,"lbm_writes_lt_1ms":743,"mutex_wait_us":1849,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:17:17.944590 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=19.056125
I20260812 06:17:18.008442 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.063s	user 0.042s	sys 0.016s Metrics: {"bytes_written":20922555,"delete_count":0,"lbm_write_time_us":27538,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:17:18.009038 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:18.027606 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.018s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.028316 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:18.039891 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.040642 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:18.272939 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.232s	user 0.178s	sys 0.047s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979619,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1114,"lbm_read_time_us":17204,"lbm_reads_lt_1ms":773,"lbm_write_time_us":46159,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":32256,"update_count":3500}
I20260812 06:17:18.273782 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:18.332002 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.058s	user 0.047s	sys 0.008s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":24980,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:18.332672 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:18.356117 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.023s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.356678 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:18.551331 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.194s	user 0.129s	sys 0.065s 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":824,"lbm_read_time_us":13871,"lbm_reads_lt_1ms":664,"lbm_write_time_us":39792,"lbm_writes_lt_1ms":643,"mutex_wait_us":485,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:17:18.551940 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:18.602025 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.050s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22369,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.602679 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:18.622077 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.019s	user 0.016s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.622651 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:18.799861 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.177s	user 0.124s	sys 0.043s 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":342,"lbm_read_time_us":10626,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32611,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:18.800735 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:18.849912 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.049s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21381,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.850423 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:19.003914 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.153s	user 0.105s	sys 0.041s 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":1201,"lbm_read_time_us":8915,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23995,"lbm_writes_lt_1ms":443,"mutex_wait_us":550,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":833920,"update_count":2000}
I20260812 06:17:19.004565 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:19.059527 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.055s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20110,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.060070 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:19.070892 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.071689 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:19.110992 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.039s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1518,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1939,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:19.111814 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling LogGCOp(1a530db31e7c4419b0cb6062c35f7615): free 112239316 bytes of WAL
I20260812 06:17:19.112078 17988 log_reader.cc:385] T 1a530db31e7c4419b0cb6062c35f7615: removed 11 log segments from log reader
I20260812 06:17:19.112135 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000014 (ops 67-71)
I20260812 06:17:19.112200 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000015 (ops 72-76)
I20260812 06:17:19.112250 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000016 (ops 77-81)
I20260812 06:17:19.112293 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000017 (ops 82-86)
I20260812 06:17:19.112345 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000018 (ops 87-91)
I20260812 06:17:19.112375 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000019 (ops 92-96)
I20260812 06:17:19.112421 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000020 (ops 97-101)
I20260812 06:17:19.112468 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000021 (ops 102-106)
I20260812 06:17:19.112512 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000022 (ops 107-111)
I20260812 06:17:19.112556 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000023 (ops 112-116)
I20260812 06:17:19.112601 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000024 (ops 117-120)
I20260812 06:17:19.139782 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: LogGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:19.140229 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615): 447 bytes on disk
I20260812 06:17:19.140684 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.141358 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=3.181125
I20260812 06:17:19.160923 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5287,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:19.161435 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:19.172077 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.172811 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:19.442075 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.269s	user 0.176s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":830,"lbm_read_time_us":18700,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46545,"lbm_writes_lt_1ms":743,"mutex_wait_us":349,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":43776,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:17:19.443265 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:19.508248 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.065s	user 0.024s	sys 0.036s Metrics: {"bytes_written":20512322,"delete_count":0,"lbm_write_time_us":28278,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.508872 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:19.521517 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.522079 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:19.755434 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.233s	user 0.124s	sys 0.096s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":13547,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36594,"lbm_writes_lt_1ms":643,"mutex_wait_us":314,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:17:19.756073 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:19.832391 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.076s	user 0.035s	sys 0.033s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":31902,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.833032 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:19.846623 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.847185 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:20.086956 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.240s	user 0.161s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":15505,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39982,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":67968,"update_count":3000}
I20260812 06:17:20.087787 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:20.160089 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.072s	user 0.041s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33519,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.160683 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:20.175088 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.175623 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:20.389616 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.214s	user 0.140s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":415,"lbm_read_time_us":15336,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37268,"lbm_writes_lt_1ms":643,"mutex_wait_us":91,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":3000}
I20260812 06:17:20.390587 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:20.454582 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.064s	user 0.034s	sys 0.024s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":26909,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.455137 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:20.467423 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.467957 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:20.691423 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.223s	user 0.164s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":577,"lbm_read_time_us":15333,"lbm_reads_lt_1ms":672,"lbm_write_time_us":40646,"lbm_writes_lt_1ms":643,"mutex_wait_us":311,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":3000}
I20260812 06:17:20.692132 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=14.095187
I20260812 06:17:20.763298 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.070s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25256,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.763799 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=6.157687
I20260812 06:17:20.789270 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.025s	user 0.013s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9087,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:20.790023 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:20.851276 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushMRSOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.061s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1357580,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":307,"dirs.run_wall_time_us":1432,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2129,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:17:20.852123 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling LogGCOp(1a530db31e7c4419b0cb6062c35f7615): free 133024610 bytes of WAL
I20260812 06:17:20.852447 17988 log_reader.cc:385] T 1a530db31e7c4419b0cb6062c35f7615: removed 13 log segments from log reader
I20260812 06:17:20.852510 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000025 (ops 121-125)
I20260812 06:17:20.852550 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000026 (ops 126-130)
I20260812 06:17:20.852587 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000027 (ops 131-135)
I20260812 06:17:20.852619 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000028 (ops 136-140)
I20260812 06:17:20.852641 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000029 (ops 141-145)
I20260812 06:17:20.852663 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000030 (ops 146-150)
I20260812 06:17:20.852702 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000031 (ops 151-154)
I20260812 06:17:20.852736 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000032 (ops 155-159)
I20260812 06:17:20.852799 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000033 (ops 160-164)
I20260812 06:17:20.852834 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000034 (ops 165-169)
I20260812 06:17:20.852856 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000035 (ops 170-174)
I20260812 06:17:20.852883 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000036 (ops 175-179)
I20260812 06:17:20.852912 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000037 (ops 180-184)
I20260812 06:17:20.888399 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: LogGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.036s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:20.889008 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615): 507 bytes on disk
I20260812 06:17:20.889521 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: UndoDeltaBlockGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.890115 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=6.157687
I20260812 06:17:20.919962 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.030s	user 0.008s	sys 0.020s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":13040,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:20.920492 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling LogGCOp(1a530db31e7c4419b0cb6062c35f7615): free 8767086 bytes of WAL
I20260812 06:17:20.920714 17988 log_reader.cc:385] T 1a530db31e7c4419b0cb6062c35f7615: removed 1 log segments from log reader
I20260812 06:17:20.920779 17988 log.cc:1079] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: Deleting log segment in path: /tmp/dist-test-taskD2jfdr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430323998-17480-0/minicluster-data/ts-0-root/wals/1a530db31e7c4419b0cb6062c35f7615/wal-000000038 (ops 185-189)
I20260812 06:17:20.922662 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: LogGCOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:20.922971 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=2.188937
I20260812 06:17:20.935778 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.936239 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615): perf score=1.000000
I20260812 06:17:21.159179 17480 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.135s	user 1.859s	sys 0.223s
I20260812 06:17:21.197757 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: MajorDeltaCompactionOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.261s	user 0.165s	sys 0.096s Metrics: {"cfile_cache_miss":934,"cfile_cache_miss_bytes":41184575,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":18981,"lbm_reads_lt_1ms":970,"lbm_write_time_us":50508,"lbm_writes_lt_1ms":943,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":4500}
I20260812 06:17:21.198448 18078 maintenance_manager.cc:419] P 2b30bded7b5947ff84268495806e3ecf: Scheduling FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615): perf score=18.063937
I20260812 06:17:21.245175 17480 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.003s	sys 0.000s
I20260812 06:17:21.245661 17480 tablet_server.cc:179] TabletServer@127.17.18.1:0 shutting down...
I20260812 06:17:21.314392 17988 maintenance_manager.cc:643] P 2b30bded7b5947ff84268495806e3ecf: FlushDeltaMemStoresOp(1a530db31e7c4419b0cb6062c35f7615) complete. Timing: real 0.116s	user 0.023s	sys 0.023s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":21675,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:21.315129 17480 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:21.315392 17480 tablet_replica.cc:333] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf: stopping tablet replica
I20260812 06:17:21.315583 17480 raft_consensus.cc:2243] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.315769 17480 raft_consensus.cc:2272] T 1a530db31e7c4419b0cb6062c35f7615 P 2b30bded7b5947ff84268495806e3ecf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.329747 17480 tablet_server.cc:196] TabletServer@127.17.18.1:0 shutdown complete.
I20260812 06:17:21.333240 17480 master.cc:562] Master@127.17.18.62:42649 shutting down...
I20260812 06:17:21.337072 17480 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.337244 17480 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.337297 17480 tablet_replica.cc:333] T 00000000000000000000000000000000 P 87752c5846984833a7e92323182febe2: stopping tablet replica
I20260812 06:17:21.349963 17480 master.cc:584] Master@127.17.18.62:42649 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5639 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11110 ms total)

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