[==========] 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:16.314208 15765 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.101.126:45363
I20260812 06:17:16.315315 15765 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:16.315976 15765 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:16.323032 15765 server_base.cc:1061] running on GCE node
W20260812 06:17:16.323010 15771 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:16.323457 15770 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:16.323589 15774 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:16.324091 15765 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.324296 15765 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:16.324355 15765 hybrid_clock.cc:648] HybridClock initialized: now 1786515436324353 us; error 0 us; skew 500 ppm
I20260812 06:17:16.326357 15765 webserver.cc:533] Webserver started at http://127.15.101.126:41379/ using document root <none> and password file <none>
I20260812 06:17:16.326975 15765 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.327070 15765 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.327346 15765 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.329298 15765 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/master-0-root/instance:
uuid: "5806132882844be8ae579daf63e6f5e8"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-rnrw"
I20260812 06:17:16.333475 15765 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:16.335944 15779 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:16.337615 15765 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:16.337790 15765 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/master-0-root
uuid: "5806132882844be8ae579daf63e6f5e8"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-rnrw"
I20260812 06:17:16.337918 15765 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-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:16.354717 15765 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.355491 15765 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:16.355726 15765 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.363714 15765 rpc_server.cc:307] RPC server started. Bound to: 127.15.101.126:45363
I20260812 06:17:16.363830 15838 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.101.126:45363 every 8 connection(s)
I20260812 06:17:16.366364 15839 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:16.373019 15839 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8: Bootstrap starting.
I20260812 06:17:16.375819 15839 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.377023 15839 log.cc:826] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:16.379209 15839 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8: No bootstrap required, opened a new log
I20260812 06:17:16.382730 15839 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5806132882844be8ae579daf63e6f5e8" member_type: VOTER }
I20260812 06:17:16.382987 15839 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.383111 15839 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5806132882844be8ae579daf63e6f5e8, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.383842 15839 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [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: "5806132882844be8ae579daf63e6f5e8" member_type: VOTER }
I20260812 06:17:16.384068 15839 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.384167 15839 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.384351 15839 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.385445 15839 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5806132882844be8ae579daf63e6f5e8" member_type: VOTER }
I20260812 06:17:16.386018 15839 leader_election.cc:304] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [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: 5806132882844be8ae579daf63e6f5e8; no voters: 
I20260812 06:17:16.386457 15839 leader_election.cc:290] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.386637 15842 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.386929 15842 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 1 LEADER]: Becoming Leader. State: Replica: 5806132882844be8ae579daf63e6f5e8, State: Running, Role: LEADER
I20260812 06:17:16.387459 15842 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [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: "5806132882844be8ae579daf63e6f5e8" member_type: VOTER }
I20260812 06:17:16.387727 15839 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:16.389679 15843 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5806132882844be8ae579daf63e6f5e8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5806132882844be8ae579daf63e6f5e8" member_type: VOTER } }
I20260812 06:17:16.389812 15843 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.389750 15844 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5806132882844be8ae579daf63e6f5e8. Latest consensus state: current_term: 1 leader_uuid: "5806132882844be8ae579daf63e6f5e8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5806132882844be8ae579daf63e6f5e8" member_type: VOTER } }
I20260812 06:17:16.389868 15844 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.390375 15855 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:16.390583 15765 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:16.393378 15855 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:16.398766 15855 catalog_manager.cc:1383] Generated new cluster ID: 4e99076fee99403db321acadf34fe74a
I20260812 06:17:16.398859 15855 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:16.406314 15855 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:16.407564 15855 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:16.417085 15855 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8: Generated new TSK 0
I20260812 06:17:16.418092 15855 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:16.423502 15765 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:16.427229 15865 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:16.427346 15765 server_base.cc:1061] running on GCE node
W20260812 06:17:16.427518 15866 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:16.427537 15868 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:16.427850 15765 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.427906 15765 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:16.427930 15765 hybrid_clock.cc:648] HybridClock initialized: now 1786515436427930 us; error 0 us; skew 500 ppm
I20260812 06:17:16.429117 15765 webserver.cc:533] Webserver started at http://127.15.101.65:46037/ using document root <none> and password file <none>
I20260812 06:17:16.429318 15765 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.429383 15765 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.429455 15765 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.429929 15765 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/instance:
uuid: "c0130d25cee944b29218e01de00cf4a4"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-rnrw"
I20260812 06:17:16.431910 15765 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:16.433193 15875 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:16.433506 15765 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:16.433580 15765 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root
uuid: "c0130d25cee944b29218e01de00cf4a4"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-rnrw"
I20260812 06:17:16.433681 15765 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-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:16.441213 15765 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.441740 15765 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.442385 15765 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:16.443383 15765 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:16.443439 15765 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.443513 15765 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:16.443552 15765 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.450686 15765 rpc_server.cc:307] RPC server started. Bound to: 127.15.101.65:40075
I20260812 06:17:16.450758 15943 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.101.65:40075 every 8 connection(s)
I20260812 06:17:16.469928 15944 heartbeater.cc:344] Connected to a master server at 127.15.101.126:45363
I20260812 06:17:16.470239 15944 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:16.470821 15944 heartbeater.cc:507] Master 127.15.101.126:45363 requested a full tablet report, sending...
I20260812 06:17:16.472433 15796 ts_manager.cc:194] Registered new tserver with Master: c0130d25cee944b29218e01de00cf4a4 (127.15.101.65:40075)
I20260812 06:17:16.472747 15765 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.021310292s
I20260812 06:17:16.473846 15796 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39814
I20260812 06:17:16.484104 15796 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39824:
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:16.499310 15906 tablet_service.cc:1511] Processing CreateTablet for tablet 8ca73cff8035448e98150185a9ba19eb (DEFAULT_TABLE table=heavy-update-compaction-test [id=1e8682ceec85436b8d29c2ff19a98272]), partition=
I20260812 06:17:16.499804 15906 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8ca73cff8035448e98150185a9ba19eb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:16.502879 15958 tablet_bootstrap.cc:492] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Bootstrap starting.
I20260812 06:17:16.504215 15958 tablet_bootstrap.cc:654] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.505733 15958 tablet_bootstrap.cc:492] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: No bootstrap required, opened a new log
I20260812 06:17:16.505863 15958 ts_tablet_manager.cc:1403] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:16.506420 15958 raft_consensus.cc:359] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c0130d25cee944b29218e01de00cf4a4" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 40075 } }
I20260812 06:17:16.506561 15958 raft_consensus.cc:385] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.506659 15958 raft_consensus.cc:740] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c0130d25cee944b29218e01de00cf4a4, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.506810 15958 consensus_queue.cc:260] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [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: "c0130d25cee944b29218e01de00cf4a4" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 40075 } }
I20260812 06:17:16.506912 15958 raft_consensus.cc:399] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.506994 15958 raft_consensus.cc:493] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.507067 15958 raft_consensus.cc:3060] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.508141 15958 raft_consensus.cc:515] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c0130d25cee944b29218e01de00cf4a4" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 40075 } }
I20260812 06:17:16.508298 15958 leader_election.cc:304] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [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: c0130d25cee944b29218e01de00cf4a4; no voters: 
I20260812 06:17:16.508536 15958 leader_election.cc:290] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.508737 15960 raft_consensus.cc:2804] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.508996 15958 ts_tablet_manager.cc:1434] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:16.509037 15960 raft_consensus.cc:697] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 1 LEADER]: Becoming Leader. State: Replica: c0130d25cee944b29218e01de00cf4a4, State: Running, Role: LEADER
I20260812 06:17:16.509276 15960 consensus_queue.cc:237] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [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: "c0130d25cee944b29218e01de00cf4a4" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 40075 } }
I20260812 06:17:16.509465 15944 heartbeater.cc:499] Master 127.15.101.126:45363 was elected leader, sending a full tablet report...
I20260812 06:17:16.512199 15796 catalog_manager.cc:5719] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 reported cstate change: term changed from 0 to 1, leader changed from <none> to c0130d25cee944b29218e01de00cf4a4 (127.15.101.65). New cstate: current_term: 1 leader_uuid: "c0130d25cee944b29218e01de00cf4a4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c0130d25cee944b29218e01de00cf4a4" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 40075 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:16.596319 15765 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.075s	user 0.026s	sys 0.009s
I20260812 06:17:16.702201 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushMRSOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.125253
I20260812 06:17:16.838660 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushMRSOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.136s	user 0.125s	sys 0.008s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":82,"delete_count":0,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":913,"drs_written":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4,"lbm_write_time_us":29450,"lbm_writes_lt_1ms":457,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"update_count":1000}
I20260812 06:17:16.839869 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling LogGCOp(8ca73cff8035448e98150185a9ba19eb): free 8725963 bytes of WAL
I20260812 06:17:16.840197 15881 log_reader.cc:385] T 8ca73cff8035448e98150185a9ba19eb: removed 1 log segments from log reader
I20260812 06:17:16.840268 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000001 (ops 1-6)
I20260812 06:17:16.842983 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: LogGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:16.843338 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:16.860755 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.861209 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:16.988801 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.127s	user 0.099s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":7272,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23368,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":375,"threads_started":5,"update_count":1500}
I20260812 06:17:16.989409 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb): 8206537 bytes on disk
I20260812 06:17:16.990059 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.992012 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=7.149875
I20260812 06:17:17.018325 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.026s	user 0.007s	sys 0.018s Metrics: {"bytes_written":8615325,"delete_count":0,"lbm_write_time_us":11514,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:17.018923 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:17.034744 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6131,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.035449 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:17.157023 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.121s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487928,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":828,"lbm_read_time_us":8500,"lbm_reads_lt_1ms":364,"lbm_write_time_us":19645,"lbm_writes_lt_1ms":343,"mutex_wait_us":375,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":80512,"update_count":1500}
I20260812 06:17:17.157752 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:17.208781 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.051s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19889,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.209290 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:17.221704 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.222584 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:17.353567 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.131s	user 0.099s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":516,"lbm_read_time_us":10547,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21914,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:17.354369 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:17.405217 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.050s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16386,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.405885 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:17.417574 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.418192 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:17.546231 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.128s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":9664,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24339,"lbm_writes_lt_1ms":443,"mutex_wait_us":94,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:17.546888 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:17.591710 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.045s	user 0.012s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13801,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.592346 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:17.603505 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4233,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.603996 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:17.753948 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.150s	user 0.101s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":959,"lbm_read_time_us":11004,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24086,"lbm_writes_lt_1ms":443,"mutex_wait_us":293,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:17.754750 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:17.804404 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.049s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.805012 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:17.820366 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.821018 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:17.946275 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.125s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":9407,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22680,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2000}
I20260812 06:17:17.946816 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:17.991567 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.045s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15951,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.992118 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:18.003343 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.004171 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:18.135655 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.131s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":9409,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25221,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":53760,"update_count":2000}
I20260812 06:17:18.136209 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:18.180131 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.044s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.180823 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:18.192708 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.193470 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushMRSOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:18.227365 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushMRSOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1572,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1543,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:18.228238 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling LogGCOp(8ca73cff8035448e98150185a9ba19eb): free 124257239 bytes of WAL
I20260812 06:17:18.228492 15881 log_reader.cc:385] T 8ca73cff8035448e98150185a9ba19eb: removed 12 log segments from log reader
I20260812 06:17:18.228535 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000002 (ops 7-11)
I20260812 06:17:18.228648 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000003 (ops 12-16)
I20260812 06:17:18.228693 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000004 (ops 17-21)
I20260812 06:17:18.228734 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000005 (ops 22-26)
I20260812 06:17:18.228775 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000006 (ops 27-30)
I20260812 06:17:18.228814 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000007 (ops 31-35)
I20260812 06:17:18.228854 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000008 (ops 36-40)
I20260812 06:17:18.228894 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000009 (ops 41-45)
I20260812 06:17:18.228935 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000010 (ops 46-50)
I20260812 06:17:18.228979 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000011 (ops 51-55)
I20260812 06:17:18.229014 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000012 (ops 56-60)
I20260812 06:17:18.229038 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000013 (ops 61-65)
I20260812 06:17:18.258306 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: LogGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.030s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:17:18.258927 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb): 473 bytes on disk
I20260812 06:17:18.259640 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.260162 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=3.181125
I20260812 06:17:18.274307 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4964173,"delete_count":0,"lbm_write_time_us":5804,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:17:18.274798 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:18.286306 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3683,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:18.286854 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:18.464293 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.177s	user 0.135s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795394,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3396,"lbm_read_time_us":12350,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35924,"lbm_writes_lt_1ms":643,"mutex_wait_us":2680,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23040,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:18.465096 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=14.095187
I20260812 06:17:18.522063 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.057s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25608,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.522543 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:18.536078 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.536919 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:18.707641 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.170s	user 0.129s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1663,"lbm_read_time_us":12847,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32774,"lbm_writes_lt_1ms":543,"mutex_wait_us":367,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:17:18.708732 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=12.110812
I20260812 06:17:18.753348 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":19465,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:17:18.753973 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.196750
I20260812 06:17:18.765225 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3685,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:18.765753 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:18.918931 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.153s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":10423,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26543,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:18.919703 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=11.118625
I20260812 06:17:18.959226 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.039s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16678,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:18.959918 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:18.978645 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.019s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6024,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.979235 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:19.126317 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.147s	user 0.096s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590338,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":7713,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29423,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:19.127069 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:19.159358 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.032s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14172,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.159929 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:19.177407 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.017s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.177911 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:19.312105 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.134s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":615,"lbm_read_time_us":11463,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26446,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:17:19.312778 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:19.349817 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.037s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16283,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.350457 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:19.368927 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.018s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.369750 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:19.494710 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.125s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":9855,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23515,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:17:19.495559 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:19.552142 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.056s	user 0.020s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19631,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.552848 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:19.565075 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.565622 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:19.729880 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.164s	user 0.116s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":12298,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26334,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.731076 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:19.780977 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.050s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17210,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.781594 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:19.793373 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.794198 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushMRSOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:19.830099 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushMRSOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.036s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1458,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1509,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:19.830996 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling LogGCOp(8ca73cff8035448e98150185a9ba19eb): free 133024332 bytes of WAL
I20260812 06:17:19.831432 15881 log_reader.cc:385] T 8ca73cff8035448e98150185a9ba19eb: removed 13 log segments from log reader
I20260812 06:17:19.831506 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000014 (ops 66-70)
I20260812 06:17:19.831579 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000015 (ops 71-75)
I20260812 06:17:19.831619 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000016 (ops 76-80)
I20260812 06:17:19.831650 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000017 (ops 81-85)
I20260812 06:17:19.831723 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000018 (ops 86-90)
I20260812 06:17:19.831768 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000019 (ops 91-95)
I20260812 06:17:19.831810 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000020 (ops 96-100)
I20260812 06:17:19.831847 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000021 (ops 101-104)
I20260812 06:17:19.831889 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000022 (ops 105-109)
I20260812 06:17:19.831924 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000023 (ops 110-114)
I20260812 06:17:19.831967 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000024 (ops 115-119)
I20260812 06:17:19.832010 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000025 (ops 120-124)
I20260812 06:17:19.832052 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000026 (ops 125-129)
I20260812 06:17:19.862946 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: LogGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.032s	user 0.001s	sys 0.029s Metrics: {}
I20260812 06:17:19.863703 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb): 482 bytes on disk
I20260812 06:17:19.864619 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.865394 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=5.165500
I20260812 06:17:19.893508 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.028s	user 0.016s	sys 0.011s Metrics: {"bytes_written":6933326,"delete_count":0,"lbm_write_time_us":8186,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:17:19.894476 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:19.906598 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.012s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1271927,"delete_count":0,"lbm_write_time_us":2430,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:17:19.907276 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:20.115356 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.208s	user 0.142s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795339,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1414,"lbm_read_time_us":14006,"lbm_reads_lt_1ms":670,"lbm_write_time_us":35281,"lbm_writes_lt_1ms":643,"mutex_wait_us":1537,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:17:20.116465 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=14.095187
I20260812 06:17:20.188736 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.072s	user 0.039s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.189599 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:20.204720 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.205464 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:20.403112 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.197s	user 0.119s	sys 0.078s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1185,"lbm_read_time_us":13570,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33037,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2500}
I20260812 06:17:20.403735 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=14.095187
I20260812 06:17:20.461812 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.058s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25887,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.462483 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:20.487828 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.025s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.488724 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:20.683004 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.194s	user 0.135s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":12588,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33070,"lbm_writes_lt_1ms":543,"mutex_wait_us":86,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:20.683815 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=11.118625
I20260812 06:17:20.735303 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.051s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19660,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:20.736022 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:20.750042 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.750595 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:20.760885 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3716,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.761445 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:20.965345 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.204s	user 0.156s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":324,"lbm_read_time_us":12225,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36670,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:17:20.966329 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:21.012718 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.046s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20068,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.013396 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:21.030683 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.031190 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:21.190192 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.159s	user 0.128s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":8951,"lbm_reads_lt_1ms":472,"lbm_write_time_us":35697,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:17:21.190847 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:21.252338 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.061s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21052,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.253612 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:21.266782 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.267850 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:21.402974 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.135s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1121,"lbm_read_time_us":9231,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24674,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2000}
I20260812 06:17:21.403872 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=10.126437
I20260812 06:17:21.458273 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.054s	user 0.026s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20246,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.458925 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:21.471153 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.471696 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushMRSOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:21.527500 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushMRSOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.056s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":435,"dirs.run_wall_time_us":2146,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1701,"lbm_writes_lt_1ms":39,"mutex_wait_us":3,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:21.528499 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling LogGCOp(8ca73cff8035448e98150185a9ba19eb): free 115943483 bytes of WAL
I20260812 06:17:21.528831 15881 log_reader.cc:385] T 8ca73cff8035448e98150185a9ba19eb: removed 11 log segments from log reader
I20260812 06:17:21.528877 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000027 (ops 130-134)
I20260812 06:17:21.528932 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000028 (ops 135-139)
I20260812 06:17:21.528977 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000029 (ops 140-144)
I20260812 06:17:21.529021 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000030 (ops 145-149)
I20260812 06:17:21.529086 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000031 (ops 150-154)
I20260812 06:17:21.529129 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000032 (ops 155-159)
I20260812 06:17:21.529172 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000033 (ops 160-164)
I20260812 06:17:21.529212 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000034 (ops 165-169)
I20260812 06:17:21.529250 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000035 (ops 170-174)
I20260812 06:17:21.529289 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000036 (ops 175-179)
I20260812 06:17:21.529335 15881 log.cc:1079] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/8ca73cff8035448e98150185a9ba19eb/wal-000000037 (ops 180-184)
I20260812 06:17:21.559104 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: LogGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:21.559598 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=3.181125
I20260812 06:17:21.574625 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":5347,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:17:21.575316 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:21.586043 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3764,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:17:21.586649 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb): 463 bytes on disk
I20260812 06:17:21.587146 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: UndoDeltaBlockGCOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:21.587953 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:21.800477 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.212s	user 0.151s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795387,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":693,"lbm_read_time_us":16348,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33604,"lbm_writes_lt_1ms":643,"mutex_wait_us":387,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26112,"thread_start_us":119,"threads_started":1,"update_count":3000}
I20260812 06:17:21.801396 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=14.095187
I20260812 06:17:21.863490 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.062s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.864059 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb): perf score=2.188937
I20260812 06:17:21.875453 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: FlushDeltaMemStoresOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.875932 15945 maintenance_manager.cc:419] P c0130d25cee944b29218e01de00cf4a4: Scheduling MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb): perf score=1.000000
I20260812 06:17:21.910466 15765 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.314s	user 1.945s	sys 0.138s
I20260812 06:17:21.984490 15765 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.001s	sys 0.000s
I20260812 06:17:21.985224 15765 tablet_server.cc:179] TabletServer@127.15.101.65:0 shutting down...
I20260812 06:17:22.030858 15881 maintenance_manager.cc:643] P c0130d25cee944b29218e01de00cf4a4: MajorDeltaCompactionOp(8ca73cff8035448e98150185a9ba19eb) complete. Timing: real 0.155s	user 0.092s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1164,"lbm_read_time_us":12307,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26339,"lbm_writes_lt_1ms":543,"mutex_wait_us":167,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.031752 15765 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:22.032308 15765 tablet_replica.cc:333] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4: stopping tablet replica
I20260812 06:17:22.032617 15765 raft_consensus.cc:2243] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.032889 15765 raft_consensus.cc:2272] T 8ca73cff8035448e98150185a9ba19eb P c0130d25cee944b29218e01de00cf4a4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.049861 15765 tablet_server.cc:196] TabletServer@127.15.101.65:0 shutdown complete.
I20260812 06:17:22.078217 15765 master.cc:562] Master@127.15.101.126:45363 shutting down...
I20260812 06:17:22.083005 15765 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.083200 15765 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.083258 15765 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5806132882844be8ae579daf63e6f5e8: stopping tablet replica
I20260812 06:17:22.095819 15765 master.cc:584] Master@127.15.101.126:45363 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5877 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:22.203510 15765 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.101.126:43317
I20260812 06:17:22.203881 15765 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:22.206238 15979 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:22.206302 15983 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:22.206302 15981 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:22.206633 15765 server_base.cc:1061] running on GCE node
I20260812 06:17:22.206780 15765 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:22.206806 15765 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:22.206821 15765 hybrid_clock.cc:648] HybridClock initialized: now 1786515442206821 us; error 0 us; skew 500 ppm
I20260812 06:17:22.208356 15765 webserver.cc:533] Webserver started at http://127.15.101.126:43903/ using document root <none> and password file <none>
I20260812 06:17:22.208514 15765 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:22.208648 15765 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:22.208721 15765 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:22.209096 15765 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/master-0-root/instance:
uuid: "d2da915bebb44b4686e844396706c31b"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-rnrw"
I20260812 06:17:22.210633 15765 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:22.211622 15988 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:22.211884 15765 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:22.211983 15765 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/master-0-root
uuid: "d2da915bebb44b4686e844396706c31b"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-rnrw"
I20260812 06:17:22.212077 15765 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-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:22.221963 15765 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:22.222426 15765 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:22.227066 15765 rpc_server.cc:307] RPC server started. Bound to: 127.15.101.126:43317
I20260812 06:17:22.232055 16048 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.101.126:43317 every 8 connection(s)
I20260812 06:17:22.232631 16050 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:22.234491 16050 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b: Bootstrap starting.
I20260812 06:17:22.235358 16050 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:22.236498 16050 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b: No bootstrap required, opened a new log
I20260812 06:17:22.236946 16050 raft_consensus.cc:359] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2da915bebb44b4686e844396706c31b" member_type: VOTER }
I20260812 06:17:22.237037 16050 raft_consensus.cc:385] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:22.237061 16050 raft_consensus.cc:740] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2da915bebb44b4686e844396706c31b, State: Initialized, Role: FOLLOWER
I20260812 06:17:22.237178 16050 consensus_queue.cc:260] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [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: "d2da915bebb44b4686e844396706c31b" member_type: VOTER }
I20260812 06:17:22.237246 16050 raft_consensus.cc:399] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:22.237268 16050 raft_consensus.cc:493] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:22.237298 16050 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:22.238003 16050 raft_consensus.cc:515] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2da915bebb44b4686e844396706c31b" member_type: VOTER }
I20260812 06:17:22.238171 16050 leader_election.cc:304] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [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: d2da915bebb44b4686e844396706c31b; no voters: 
I20260812 06:17:22.238366 16050 leader_election.cc:290] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:22.238523 16053 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:22.238780 16053 raft_consensus.cc:697] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 1 LEADER]: Becoming Leader. State: Replica: d2da915bebb44b4686e844396706c31b, State: Running, Role: LEADER
I20260812 06:17:22.238932 16050 sys_catalog.cc:565] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:22.238938 16053 consensus_queue.cc:237] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [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: "d2da915bebb44b4686e844396706c31b" member_type: VOTER }
I20260812 06:17:22.239497 16054 sys_catalog.cc:455] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d2da915bebb44b4686e844396706c31b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2da915bebb44b4686e844396706c31b" member_type: VOTER } }
I20260812 06:17:22.239543 16055 sys_catalog.cc:455] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [sys.catalog]: SysCatalogTable state changed. Reason: New leader d2da915bebb44b4686e844396706c31b. Latest consensus state: current_term: 1 leader_uuid: "d2da915bebb44b4686e844396706c31b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2da915bebb44b4686e844396706c31b" member_type: VOTER } }
I20260812 06:17:22.239697 16055 sys_catalog.cc:458] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:22.239919 16054 sys_catalog.cc:458] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:22.240204 16060 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:22.241274 16060 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:22.241526 15765 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:22.243274 16060 catalog_manager.cc:1383] Generated new cluster ID: ab21d223c78a42c2a7fdf25de699ca9b
I20260812 06:17:22.243326 16060 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:22.253088 16060 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:22.253729 16060 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:22.265333 16060 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b: Generated new TSK 0
I20260812 06:17:22.265542 16060 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:22.274062 15765 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:22.276095 16075 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:22.276162 15765 server_base.cc:1061] running on GCE node
W20260812 06:17:22.276113 16072 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:22.276270 16073 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:22.276479 15765 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:22.276664 15765 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:22.276705 15765 hybrid_clock.cc:648] HybridClock initialized: now 1786515442276704 us; error 0 us; skew 500 ppm
I20260812 06:17:22.277673 15765 webserver.cc:533] Webserver started at http://127.15.101.65:45547/ using document root <none> and password file <none>
I20260812 06:17:22.277855 15765 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:22.277930 15765 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:22.278030 15765 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:22.278460 15765 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/instance:
uuid: "bcde6796df5d4365862fa4be3dc20ccc"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-rnrw"
I20260812 06:17:22.280105 15765 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:22.281307 16080 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:22.281584 15765 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:22.281679 15765 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root
uuid: "bcde6796df5d4365862fa4be3dc20ccc"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-rnrw"
I20260812 06:17:22.281773 15765 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-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:22.293980 15765 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:22.294421 15765 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:22.294766 15765 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:22.295269 15765 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:22.295329 15765 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:22.295383 15765 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:22.295431 15765 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:22.300132 15765 rpc_server.cc:307] RPC server started. Bound to: 127.15.101.65:32879
I20260812 06:17:22.301254 16153 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.101.65:32879 every 8 connection(s)
I20260812 06:17:22.312820 16154 heartbeater.cc:344] Connected to a master server at 127.15.101.126:43317
I20260812 06:17:22.313005 16154 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:22.313355 16154 heartbeater.cc:507] Master 127.15.101.126:43317 requested a full tablet report, sending...
I20260812 06:17:22.314198 16008 ts_manager.cc:194] Registered new tserver with Master: bcde6796df5d4365862fa4be3dc20ccc (127.15.101.65:32879)
I20260812 06:17:22.314492 15765 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013339869s
I20260812 06:17:22.315104 16008 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38322
I20260812 06:17:22.322891 16008 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38332:
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:22.332480 16112 tablet_service.cc:1511] Processing CreateTablet for tablet 591f10709f1b4dbfb161d578d54722e3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=32ab7ddedf74457b9873d02599d0dd22]), partition=
I20260812 06:17:22.332907 16112 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 591f10709f1b4dbfb161d578d54722e3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:22.335299 16168 tablet_bootstrap.cc:492] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Bootstrap starting.
I20260812 06:17:22.336344 16168 tablet_bootstrap.cc:654] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:22.337832 16168 tablet_bootstrap.cc:492] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: No bootstrap required, opened a new log
I20260812 06:17:22.337956 16168 ts_tablet_manager.cc:1403] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:22.338531 16168 raft_consensus.cc:359] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcde6796df5d4365862fa4be3dc20ccc" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 32879 } }
I20260812 06:17:22.338701 16168 raft_consensus.cc:385] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:22.338724 16168 raft_consensus.cc:740] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bcde6796df5d4365862fa4be3dc20ccc, State: Initialized, Role: FOLLOWER
I20260812 06:17:22.338865 16168 consensus_queue.cc:260] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [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: "bcde6796df5d4365862fa4be3dc20ccc" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 32879 } }
I20260812 06:17:22.338950 16168 raft_consensus.cc:399] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:22.338974 16168 raft_consensus.cc:493] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:22.339006 16168 raft_consensus.cc:3060] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:22.339814 16168 raft_consensus.cc:515] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcde6796df5d4365862fa4be3dc20ccc" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 32879 } }
I20260812 06:17:22.339995 16168 leader_election.cc:304] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [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: bcde6796df5d4365862fa4be3dc20ccc; no voters: 
I20260812 06:17:22.340214 16168 leader_election.cc:290] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:22.340386 16171 raft_consensus.cc:2804] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:22.340641 16171 raft_consensus.cc:697] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 1 LEADER]: Becoming Leader. State: Replica: bcde6796df5d4365862fa4be3dc20ccc, State: Running, Role: LEADER
I20260812 06:17:22.340646 16154 heartbeater.cc:499] Master 127.15.101.126:43317 was elected leader, sending a full tablet report...
I20260812 06:17:22.340826 16171 consensus_queue.cc:237] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [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: "bcde6796df5d4365862fa4be3dc20ccc" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 32879 } }
I20260812 06:17:22.340646 16168 ts_tablet_manager.cc:1434] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:22.343087 16008 catalog_manager.cc:5719] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc reported cstate change: term changed from 0 to 1, leader changed from <none> to bcde6796df5d4365862fa4be3dc20ccc (127.15.101.65). New cstate: current_term: 1 leader_uuid: "bcde6796df5d4365862fa4be3dc20ccc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcde6796df5d4365862fa4be3dc20ccc" member_type: VOTER last_known_addr { host: "127.15.101.65" port: 32879 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:22.410025 15765 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.008s
I20260812 06:17:22.551730 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushMRSOp(591f10709f1b4dbfb161d578d54722e3): perf score=15.086190
I20260812 06:17:22.710111 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushMRSOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.158s	user 0.110s	sys 0.047s Metrics: {"bytes_written":11897250,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":891,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37588,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:17:22.710870 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling LogGCOp(591f10709f1b4dbfb161d578d54722e3): free 20743880 bytes of WAL
I20260812 06:17:22.711118 16087 log_reader.cc:385] T 591f10709f1b4dbfb161d578d54722e3: removed 2 log segments from log reader
I20260812 06:17:22.711165 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000001 (ops 1-6)
I20260812 06:17:22.711283 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000002 (ops 7-11)
I20260812 06:17:22.717098 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: LogGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:22.717600 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:22.734297 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6543,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.734784 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3): 12719218 bytes on disk
I20260812 06:17:22.735253 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.735725 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:22.906970 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.171s	user 0.094s	sys 0.065s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":11959,"lbm_reads_lt_1ms":454,"lbm_write_time_us":25388,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":340,"threads_started":5,"update_count":1950}
I20260812 06:17:22.907589 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:22.960134 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.052s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20575,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.960686 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:22.972748 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.973255 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:23.135413 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.162s	user 0.117s	sys 0.043s 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":158,"lbm_read_time_us":10349,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32895,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:17:23.136111 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=11.118625
I20260812 06:17:23.172006 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.036s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14768,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:23.172739 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:23.202687 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.030s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:23.203429 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:23.214969 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.215772 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:23.376060 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.160s	user 0.136s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":171,"lbm_read_time_us":9583,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33293,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:17:23.376847 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=11.118625
I20260812 06:17:23.408121 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.031s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13496,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:23.409013 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:23.427207 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5256,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:23.427783 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:23.566879 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.139s	user 0.090s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":497,"lbm_read_time_us":8866,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24992,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:17:23.567776 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=10.126437
I20260812 06:17:23.610773 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.043s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18274,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.611382 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:23.624662 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4586,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.625358 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:23.761070 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.135s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":819,"lbm_read_time_us":10265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26853,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:17:23.761914 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=10.126437
I20260812 06:17:23.820228 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.058s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16093,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.820895 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:23.832719 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.833241 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:23.993046 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.160s	user 0.103s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":12505,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24981,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38400,"update_count":2000}
I20260812 06:17:23.993848 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=10.126437
I20260812 06:17:24.039003 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.045s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19637,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.039584 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:24.056095 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.056756 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushMRSOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:24.090395 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushMRSOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1482,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2145,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:24.091146 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling LogGCOp(591f10709f1b4dbfb161d578d54722e3): free 115943180 bytes of WAL
I20260812 06:17:24.091404 16087 log_reader.cc:385] T 591f10709f1b4dbfb161d578d54722e3: removed 11 log segments from log reader
I20260812 06:17:24.091472 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000003 (ops 12-16)
I20260812 06:17:24.091526 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000004 (ops 17-21)
I20260812 06:17:24.091563 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000005 (ops 22-26)
I20260812 06:17:24.091601 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000006 (ops 27-31)
I20260812 06:17:24.091634 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000007 (ops 32-36)
I20260812 06:17:24.091657 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000008 (ops 37-41)
I20260812 06:17:24.091681 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000009 (ops 42-46)
I20260812 06:17:24.091714 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000010 (ops 47-51)
I20260812 06:17:24.091750 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000011 (ops 52-56)
I20260812 06:17:24.091789 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000012 (ops 57-61)
I20260812 06:17:24.091825 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000013 (ops 62-66)
I20260812 06:17:24.119045 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: LogGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:24.119479 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:24.134181 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.014s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.134617 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:24.156823 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.022s	user 0.015s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.157506 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:24.368943 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.211s	user 0.147s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":632,"lbm_read_time_us":14305,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35132,"lbm_writes_lt_1ms":643,"mutex_wait_us":101,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:17:24.369704 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3): 462 bytes on disk
I20260812 06:17:24.370246 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.371033 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:24.438793 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.068s	user 0.034s	sys 0.031s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":28843,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.439337 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=3.181125
I20260812 06:17:24.454790 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:24.455237 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:24.465457 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.465947 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:24.678869 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.213s	user 0.132s	sys 0.080s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":349,"lbm_read_time_us":16564,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36360,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":3000}
I20260812 06:17:24.679538 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:24.733084 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.053s	user 0.028s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22908,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.733644 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:24.750229 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.750725 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:24.937783 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.187s	user 0.105s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":13804,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30801,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:24.938530 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:25.006233 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.068s	user 0.043s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24920,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.006906 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:25.018872 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.019366 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:25.204921 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.185s	user 0.125s	sys 0.060s 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":894,"lbm_read_time_us":12659,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30571,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:25.205730 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=10.126437
I20260812 06:17:25.250365 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.250936 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:25.262017 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.262568 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:25.404153 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.141s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":10097,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25440,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:17:25.404959 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=10.126437
I20260812 06:17:25.452138 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.047s	user 0.012s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17606,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.452744 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:25.464394 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.465292 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:25.593127 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.128s	user 0.111s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1174,"lbm_read_time_us":8270,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24202,"lbm_writes_lt_1ms":443,"mutex_wait_us":399,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:17:25.593684 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=10.126437
I20260812 06:17:25.642388 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.048s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16177,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.642967 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:25.654968 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.655694 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushMRSOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:25.688943 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushMRSOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1790,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1617,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":16768}
I20260812 06:17:25.689648 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling LogGCOp(591f10709f1b4dbfb161d578d54722e3): free 121006381 bytes of WAL
I20260812 06:17:25.689934 16087 log_reader.cc:385] T 591f10709f1b4dbfb161d578d54722e3: removed 12 log segments from log reader
I20260812 06:17:25.689978 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000014 (ops 67-71)
I20260812 06:17:25.690008 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000015 (ops 72-76)
I20260812 06:17:25.690025 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000016 (ops 77-81)
I20260812 06:17:25.690085 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000017 (ops 82-86)
I20260812 06:17:25.690137 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000018 (ops 87-90)
I20260812 06:17:25.690174 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000019 (ops 91-95)
I20260812 06:17:25.690220 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000020 (ops 96-100)
I20260812 06:17:25.690261 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000021 (ops 101-105)
I20260812 06:17:25.690305 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000022 (ops 106-110)
I20260812 06:17:25.690348 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000023 (ops 111-115)
I20260812 06:17:25.690387 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000024 (ops 116-120)
I20260812 06:17:25.690428 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000025 (ops 121-125)
I20260812 06:17:25.719100 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: LogGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:25.719648 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=3.181125
I20260812 06:17:25.738161 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7233,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:25.738633 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:25.749513 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.750032 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:25.937281 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.187s	user 0.133s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1250,"lbm_read_time_us":15279,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36361,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":119,"threads_started":1,"update_count":3000}
I20260812 06:17:25.938089 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3): 473 bytes on disk
I20260812 06:17:25.938763 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.939401 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:25.999588 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.060s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":26863,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.000136 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:26.023026 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.023641 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:26.189231 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.165s	user 0.114s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":876,"lbm_read_time_us":11259,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30140,"lbm_writes_lt_1ms":543,"mutex_wait_us":373,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":742528,"update_count":2500}
I20260812 06:17:26.189810 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:26.263579 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.074s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26830,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.264110 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:26.275978 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.276597 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:26.466634 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.190s	user 0.116s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":14233,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31487,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:17:26.467393 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:26.524506 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.057s	user 0.041s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.525156 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:26.538523 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.539851 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:26.715773 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.176s	user 0.115s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":10997,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31654,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2500}
I20260812 06:17:26.716593 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:26.787161 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.070s	user 0.025s	sys 0.037s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22393,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.787871 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:26.805708 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.018s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.806327 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:27.003023 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.196s	user 0.139s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":795,"lbm_read_time_us":18143,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":31933,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:17:27.004172 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=11.118625
I20260812 06:17:27.046854 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.042s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18987,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:27.047806 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:27.067240 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.019s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.067788 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:27.249194 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.181s	user 0.102s	sys 0.067s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":684,"lbm_read_time_us":10504,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26927,"lbm_writes_lt_1ms":443,"mutex_wait_us":345,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:17:27.249893 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:27.314594 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.064s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24695,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.315184 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=2.188937
I20260812 06:17:27.331830 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.332532 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushMRSOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:27.376179 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushMRSOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.043s	user 0.036s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":2130,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1935,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:27.377137 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling LogGCOp(591f10709f1b4dbfb161d578d54722e3): free 132571629 bytes of WAL
I20260812 06:17:27.378482 16087 log_reader.cc:385] T 591f10709f1b4dbfb161d578d54722e3: removed 13 log segments from log reader
I20260812 06:17:27.378650 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000026 (ops 126-130)
I20260812 06:17:27.378748 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000027 (ops 131-134)
I20260812 06:17:27.378798 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000028 (ops 135-139)
I20260812 06:17:27.378875 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000029 (ops 140-144)
I20260812 06:17:27.378926 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000030 (ops 145-149)
I20260812 06:17:27.378960 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000031 (ops 150-154)
I20260812 06:17:27.378988 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000032 (ops 155-159)
I20260812 06:17:27.379010 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000033 (ops 160-164)
I20260812 06:17:27.379400 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000034 (ops 165-169)
I20260812 06:17:27.379451 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000035 (ops 170-174)
I20260812 06:17:27.379480 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000036 (ops 175-178)
I20260812 06:17:27.379504 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000037 (ops 179-183)
I20260812 06:17:27.379558 16087 log.cc:1079] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: Deleting log segment in path: /tmp/dist-test-tasklBcmIu/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515436303003-15765-0/minicluster-data/ts-0-root/wals/591f10709f1b4dbfb161d578d54722e3/wal-000000038 (ops 184-188)
I20260812 06:17:27.415947 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: LogGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.038s	user 0.003s	sys 0.031s Metrics: {}
I20260812 06:17:27.416528 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3): 482 bytes on disk
I20260812 06:17:27.417241 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: UndoDeltaBlockGCOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.417948 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=3.181125
I20260812 06:17:27.433777 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":5046220,"delete_count":0,"lbm_write_time_us":6537,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:17:27.434370 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.196750
I20260812 06:17:27.446003 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:17:27.446470 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:27.682250 15765 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.272s	user 1.888s	sys 0.202s
I20260812 06:17:27.692781 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.246s	user 0.150s	sys 0.091s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979732,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15816,"lbm_reads_lt_1ms":770,"lbm_write_time_us":43540,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3500}
I20260812 06:17:27.693321 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3): perf score=14.095187
I20260812 06:17:27.726905 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: FlushDeltaMemStoresOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.033s	user 0.025s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16076,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.727494 16155 maintenance_manager.cc:419] P bcde6796df5d4365862fa4be3dc20ccc: Scheduling MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3): perf score=1.000000
I20260812 06:17:27.786293 15765 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.104s	user 0.003s	sys 0.000s
I20260812 06:17:27.786976 15765 tablet_server.cc:179] TabletServer@127.15.101.65:0 shutting down...
I20260812 06:17:27.873489 16087 maintenance_manager.cc:643] P bcde6796df5d4365862fa4be3dc20ccc: MajorDeltaCompactionOp(591f10709f1b4dbfb161d578d54722e3) complete. Timing: real 0.146s	user 0.123s	sys 0.018s 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":333,"lbm_read_time_us":7249,"lbm_reads_lt_1ms":467,"lbm_write_time_us":29313,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.874136 15765 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:27.874466 15765 tablet_replica.cc:333] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc: stopping tablet replica
I20260812 06:17:27.874630 15765 raft_consensus.cc:2243] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:27.874805 15765 raft_consensus.cc:2272] T 591f10709f1b4dbfb161d578d54722e3 P bcde6796df5d4365862fa4be3dc20ccc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:27.889890 15765 tablet_server.cc:196] TabletServer@127.15.101.65:0 shutdown complete.
I20260812 06:17:27.918107 15765 master.cc:562] Master@127.15.101.126:43317 shutting down...
I20260812 06:17:27.922627 15765 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:27.922868 15765 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:27.922978 15765 tablet_replica.cc:333] T 00000000000000000000000000000000 P d2da915bebb44b4686e844396706c31b: stopping tablet replica
I20260812 06:17:27.935649 15765 master.cc:584] Master@127.15.101.126:43317 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5835 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11714 ms total)

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