[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:27.668171 11662 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.99.190:38817
I20260812 06:18:27.669157 11662 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:27.669749 11662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.676204 11675 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:27.676211 11673 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:27.676357 11662 server_base.cc:1061] running on GCE node
W20260812 06:18:27.676553 11672 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:27.677112 11662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.677217 11662 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:27.677278 11662 hybrid_clock.cc:648] HybridClock initialized: now 1786515507677275 us; error 0 us; skew 500 ppm
I20260812 06:18:27.679279 11662 webserver.cc:533] Webserver started at http://127.11.99.190:39349/ using document root <none> and password file <none>
I20260812 06:18:27.679843 11662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.679935 11662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.680224 11662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.681972 11662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/master-0-root/instance:
uuid: "450e241b5ac3434e9769ed048bb78c25"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-w4v5"
I20260812 06:18:27.685593 11662 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:27.687762 11681 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.688823 11662 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:27.688977 11662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/master-0-root
uuid: "450e241b5ac3434e9769ed048bb78c25"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-w4v5"
I20260812 06:18:27.689090 11662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:27.713136 11662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.713855 11662 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:27.714064 11662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.722471 11772 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.99.190:38817 every 8 connection(s)
I20260812 06:18:27.722476 11662 rpc_server.cc:307] RPC server started. Bound to: 127.11.99.190:38817
I20260812 06:18:27.724890 11773 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.730168 11773 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: Bootstrap starting.
I20260812 06:18:27.732460 11773 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.733286 11773 log.cc:826] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.734818 11773 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: No bootstrap required, opened a new log
I20260812 06:18:27.737449 11773 raft_consensus.cc:359] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "450e241b5ac3434e9769ed048bb78c25" member_type: VOTER }
I20260812 06:18:27.737602 11773 raft_consensus.cc:385] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.737648 11773 raft_consensus.cc:740] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 450e241b5ac3434e9769ed048bb78c25, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.738135 11773 consensus_queue.cc:260] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [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: "450e241b5ac3434e9769ed048bb78c25" member_type: VOTER }
I20260812 06:18:27.738270 11773 raft_consensus.cc:399] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.738310 11773 raft_consensus.cc:493] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.738389 11773 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.739112 11773 raft_consensus.cc:515] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "450e241b5ac3434e9769ed048bb78c25" member_type: VOTER }
I20260812 06:18:27.739514 11773 leader_election.cc:304] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [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: 450e241b5ac3434e9769ed048bb78c25; no voters: 
I20260812 06:18:27.739809 11773 leader_election.cc:290] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.740063 11776 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.740312 11776 raft_consensus.cc:697] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 1 LEADER]: Becoming Leader. State: Replica: 450e241b5ac3434e9769ed048bb78c25, State: Running, Role: LEADER
I20260812 06:18:27.740733 11773 sys_catalog.cc:565] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.740774 11776 consensus_queue.cc:237] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [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: "450e241b5ac3434e9769ed048bb78c25" member_type: VOTER }
I20260812 06:18:27.742619 11777 sys_catalog.cc:455] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "450e241b5ac3434e9769ed048bb78c25" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "450e241b5ac3434e9769ed048bb78c25" member_type: VOTER } }
I20260812 06:18:27.742674 11778 sys_catalog.cc:455] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 450e241b5ac3434e9769ed048bb78c25. Latest consensus state: current_term: 1 leader_uuid: "450e241b5ac3434e9769ed048bb78c25" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "450e241b5ac3434e9769ed048bb78c25" member_type: VOTER } }
I20260812 06:18:27.742756 11777 sys_catalog.cc:458] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.742765 11778 sys_catalog.cc:458] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.743574 11662 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:27.745397 11804 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:27.745489 11804 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:27.745558 11798 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.746263 11798 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.750723 11798 catalog_manager.cc:1383] Generated new cluster ID: 006ec99fb67b450892f4a123d2e49bc7
I20260812 06:18:27.750785 11798 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.775493 11798 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.776363 11798 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.783855 11798 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: Generated new TSK 0
I20260812 06:18:27.784572 11798 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.808624 11662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.811753 11813 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:27.811764 11811 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:27.811868 11815 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:27.812107 11662 server_base.cc:1061] running on GCE node
I20260812 06:18:27.812340 11662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.812419 11662 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:27.812448 11662 hybrid_clock.cc:648] HybridClock initialized: now 1786515507812446 us; error 0 us; skew 500 ppm
I20260812 06:18:27.813377 11662 webserver.cc:533] Webserver started at http://127.11.99.129:43833/ using document root <none> and password file <none>
I20260812 06:18:27.813570 11662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.813649 11662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.813762 11662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.814183 11662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/instance:
uuid: "3f717a6d59ce40e49874ee9034b0ad92"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-w4v5"
I20260812 06:18:27.815872 11662 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:27.816902 11820 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.817155 11662 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:27.817217 11662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root
uuid: "3f717a6d59ce40e49874ee9034b0ad92"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-w4v5"
I20260812 06:18:27.817308 11662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:27.826663 11662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.827152 11662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.827667 11662 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.828502 11662 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.828552 11662 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.828616 11662 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.828653 11662 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.835649 11662 rpc_server.cc:307] RPC server started. Bound to: 127.11.99.129:40095
I20260812 06:18:27.835691 11915 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.99.129:40095 every 8 connection(s)
I20260812 06:18:27.849485 11918 heartbeater.cc:344] Connected to a master server at 127.11.99.190:38817
I20260812 06:18:27.849758 11918 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.850219 11918 heartbeater.cc:507] Master 127.11.99.190:38817 requested a full tablet report, sending...
I20260812 06:18:27.851629 11707 ts_manager.cc:194] Registered new tserver with Master: 3f717a6d59ce40e49874ee9034b0ad92 (127.11.99.129:40095)
I20260812 06:18:27.852099 11662 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015816701s
I20260812 06:18:27.852834 11707 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51004
I20260812 06:18:27.861389 11707 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51010:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:27.876251 11860 tablet_service.cc:1511] Processing CreateTablet for tablet 3d70e944449945bbb035df992b955ef3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=47ba40c373ab475297eade5860c3cb9a]), partition=
I20260812 06:18:27.876725 11860 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3d70e944449945bbb035df992b955ef3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.879664 11937 tablet_bootstrap.cc:492] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Bootstrap starting.
I20260812 06:18:27.880576 11937 tablet_bootstrap.cc:654] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.881709 11937 tablet_bootstrap.cc:492] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: No bootstrap required, opened a new log
I20260812 06:18:27.881798 11937 ts_tablet_manager.cc:1403] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:27.882630 11937 raft_consensus.cc:359] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f717a6d59ce40e49874ee9034b0ad92" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 40095 } }
I20260812 06:18:27.882782 11937 raft_consensus.cc:385] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.882838 11937 raft_consensus.cc:740] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3f717a6d59ce40e49874ee9034b0ad92, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.882990 11937 consensus_queue.cc:260] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [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: "3f717a6d59ce40e49874ee9034b0ad92" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 40095 } }
I20260812 06:18:27.883136 11937 raft_consensus.cc:399] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.883191 11937 raft_consensus.cc:493] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.883246 11937 raft_consensus.cc:3060] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.883991 11937 raft_consensus.cc:515] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f717a6d59ce40e49874ee9034b0ad92" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 40095 } }
I20260812 06:18:27.884148 11937 leader_election.cc:304] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [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: 3f717a6d59ce40e49874ee9034b0ad92; no voters: 
I20260812 06:18:27.884387 11937 leader_election.cc:290] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.884485 11944 raft_consensus.cc:2804] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.884661 11944 raft_consensus.cc:697] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 1 LEADER]: Becoming Leader. State: Replica: 3f717a6d59ce40e49874ee9034b0ad92, State: Running, Role: LEADER
I20260812 06:18:27.884753 11937 ts_tablet_manager.cc:1434] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:27.884809 11944 consensus_queue.cc:237] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [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: "3f717a6d59ce40e49874ee9034b0ad92" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 40095 } }
I20260812 06:18:27.885138 11918 heartbeater.cc:499] Master 127.11.99.190:38817 was elected leader, sending a full tablet report...
I20260812 06:18:27.887671 11707 catalog_manager.cc:5719] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3f717a6d59ce40e49874ee9034b0ad92 (127.11.99.129). New cstate: current_term: 1 leader_uuid: "3f717a6d59ce40e49874ee9034b0ad92" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f717a6d59ce40e49874ee9034b0ad92" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 40095 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.952525 11662 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.019s	sys 0.008s
I20260812 06:18:28.086743 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushMRSOp(3d70e944449945bbb035df992b955ef3): perf score=19.054940
I20260812 06:18:28.265705 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushMRSOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.178s	user 0.131s	sys 0.036s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":205,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":811,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43265,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":110,"threads_started":1,"update_count":1500}
I20260812 06:18:28.266779 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling LogGCOp(3d70e944449945bbb035df992b955ef3): free 20743880 bytes of WAL
I20260812 06:18:28.267134 11826 log_reader.cc:385] T 3d70e944449945bbb035df992b955ef3: removed 2 log segments from log reader
I20260812 06:18:28.267231 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000001 (ops 1-6)
I20260812 06:18:28.267308 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000002 (ops 7-11)
I20260812 06:18:28.271709 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: LogGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:28.272065 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3): 16411398 bytes on disk
I20260812 06:18:28.272632 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.273020 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:28.295133 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.022s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6679,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.295748 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:28.437541 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.142s	user 0.119s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":8091,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23129,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":424,"threads_started":5,"update_count":2000}
I20260812 06:18:28.438282 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=10.126437
I20260812 06:18:28.471714 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.033s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14328,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.472148 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:28.487802 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.015s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.488230 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:28.614452 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.126s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":8365,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24838,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:28.614974 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=11.118625
I20260812 06:18:28.648917 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.034s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14557,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.649410 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:28.664374 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5710,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.664989 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:28.791533 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.126s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":633,"lbm_read_time_us":8435,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23400,"lbm_writes_lt_1ms":443,"mutex_wait_us":287,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:28.792104 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=10.126437
I20260812 06:18:28.838275 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16097,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.838860 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:28.854921 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.855445 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:29.002831 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.147s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":968,"lbm_read_time_us":10236,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24231,"lbm_writes_lt_1ms":443,"mutex_wait_us":336,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:29.003700 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=10.126437
I20260812 06:18:29.047569 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.044s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17065,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.048031 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:29.059108 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.059859 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:29.188905 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.129s	user 0.116s	sys 0.012s 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":213,"lbm_read_time_us":9670,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26135,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:29.189484 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=10.126437
I20260812 06:18:29.235179 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21894,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.235672 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:29.259327 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.023s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9479,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.259852 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:29.391360 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.131s	user 0.111s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":692,"lbm_read_time_us":9070,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26410,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:29.392043 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=10.126437
I20260812 06:18:29.432515 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14150,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.432992 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:29.443734 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.444239 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushMRSOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:29.483421 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushMRSOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.038s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1401,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:29.484233 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling LogGCOp(3d70e944449945bbb035df992b955ef3): free 115943176 bytes of WAL
I20260812 06:18:29.484501 11826 log_reader.cc:385] T 3d70e944449945bbb035df992b955ef3: removed 11 log segments from log reader
I20260812 06:18:29.484565 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000003 (ops 12-16)
I20260812 06:18:29.484606 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000004 (ops 17-21)
I20260812 06:18:29.484637 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000005 (ops 22-26)
I20260812 06:18:29.484660 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000006 (ops 27-31)
I20260812 06:18:29.484683 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000007 (ops 32-36)
I20260812 06:18:29.484707 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000008 (ops 37-41)
I20260812 06:18:29.484741 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000009 (ops 42-46)
I20260812 06:18:29.484773 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000010 (ops 47-51)
I20260812 06:18:29.484802 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000011 (ops 52-56)
I20260812 06:18:29.484829 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000012 (ops 57-61)
I20260812 06:18:29.484858 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000013 (ops 62-66)
I20260812 06:18:29.511993 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: LogGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:29.513250 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=3.181125
I20260812 06:18:29.538286 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":5288,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:29.538767 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:29.548827 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:29.549408 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:29.739156 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.190s	user 0.108s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":774,"lbm_read_time_us":12445,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31457,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:18:29.739768 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3): 448 bytes on disk
I20260812 06:18:29.740341 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.740988 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:29.795920 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.055s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20835,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.796411 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:29.807173 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.807718 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:29.970045 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.162s	user 0.110s	sys 0.052s 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":700,"lbm_read_time_us":11586,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29451,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:29.970741 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:30.032059 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.061s	user 0.033s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23544,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:30.032646 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:30.043771 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.044242 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:30.223628 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.179s	user 0.117s	sys 0.056s 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":536,"dirs.run_cpu_time_us":1679,"dirs.run_wall_time_us":13615,"lbm_read_time_us":13632,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29505,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:30.224275 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=11.118625
I20260812 06:18:30.279016 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.055s	user 0.030s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22225,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.279767 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:30.308732 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.029s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6461,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.309227 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:30.319669 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.320132 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:30.497467 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.177s	user 0.104s	sys 0.063s 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":201,"lbm_read_time_us":11138,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32622,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":114,"threads_started":2,"update_count":2500}
I20260812 06:18:30.498042 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:30.562520 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.064s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20776,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.563215 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:30.579579 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.580149 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:30.768908 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.189s	user 0.128s	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":123,"lbm_read_time_us":14318,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32287,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:18:30.769804 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=11.118625
I20260812 06:18:30.809693 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17769,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.810309 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:30.821662 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.822161 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:30.960176 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.138s	user 0.114s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":8754,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26386,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:18:30.960868 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=10.126437
I20260812 06:18:30.997052 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14816,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.997712 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:31.011062 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.011576 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushMRSOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:31.045365 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushMRSOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.034s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1220,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1899,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:31.046214 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling LogGCOp(3d70e944449945bbb035df992b955ef3): free 117302579 bytes of WAL
I20260812 06:18:31.046495 11826 log_reader.cc:385] T 3d70e944449945bbb035df992b955ef3: removed 12 log segments from log reader
I20260812 06:18:31.046559 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000014 (ops 67-71)
I20260812 06:18:31.046597 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000015 (ops 72-76)
I20260812 06:18:31.046626 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000016 (ops 77-81)
I20260812 06:18:31.046649 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000017 (ops 82-86)
I20260812 06:18:31.046672 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000018 (ops 87-90)
I20260812 06:18:31.046695 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000019 (ops 91-95)
I20260812 06:18:31.046731 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000020 (ops 96-100)
I20260812 06:18:31.046761 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000021 (ops 101-105)
I20260812 06:18:31.046799 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000022 (ops 106-110)
I20260812 06:18:31.046828 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000023 (ops 111-114)
I20260812 06:18:31.046870 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000024 (ops 115-119)
I20260812 06:18:31.046898 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000025 (ops 120-124)
I20260812 06:18:31.074066 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: LogGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:18:31.074584 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=4.173312
I20260812 06:18:31.088622 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":5497489,"delete_count":0,"lbm_write_time_us":5781,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:18:31.089068 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling LogGCOp(3d70e944449945bbb035df992b955ef3): free 12017931 bytes of WAL
I20260812 06:18:31.089282 11826 log_reader.cc:385] T 3d70e944449945bbb035df992b955ef3: removed 1 log segments from log reader
I20260812 06:18:31.089347 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000026 (ops 125-129)
I20260812 06:18:31.091684 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: LogGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:31.091979 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3): 482 bytes on disk
I20260812 06:18:31.092374 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.092824 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=1.196750
I20260812 06:18:31.108495 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:31.108992 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:31.275799 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.167s	user 0.116s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877308,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":584,"lbm_read_time_us":12332,"lbm_reads_lt_1ms":666,"lbm_write_time_us":32630,"lbm_writes_lt_1ms":643,"mutex_wait_us":282,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:18:31.276579 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:31.324532 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.048s	user 0.016s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22102,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.325186 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:31.341959 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.017s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.342423 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:31.481361 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.139s	user 0.109s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":8851,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27786,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:31.481974 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:31.529621 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.047s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19759,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.530107 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:31.542039 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.542698 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:31.700485 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.158s	user 0.130s	sys 0.022s 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":127,"lbm_read_time_us":9923,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31200,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:18:31.701099 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:31.758460 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.057s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24331,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.759030 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:31.777176 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.777640 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:31.939235 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.161s	user 0.119s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":552,"lbm_read_time_us":10609,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29940,"lbm_writes_lt_1ms":543,"mutex_wait_us":265,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:18:31.940023 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:31.996801 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.057s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23544,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.997277 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:32.008518 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.009033 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:32.194476 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.185s	user 0.130s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":12902,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29924,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:32.195318 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:32.247588 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.052s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23015,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.248198 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:32.409835 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.161s	user 0.113s	sys 0.040s 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":394,"lbm_read_time_us":10177,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25579,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:18:32.410386 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=14.095187
I20260812 06:18:32.460398 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.050s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21877,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.461030 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:32.472319 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.472857 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushMRSOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:32.509156 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushMRSOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.036s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1417,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2114,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:32.509815 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling LogGCOp(3d70e944449945bbb035df992b955ef3): free 121006704 bytes of WAL
I20260812 06:18:32.510042 11826 log_reader.cc:385] T 3d70e944449945bbb035df992b955ef3: removed 12 log segments from log reader
I20260812 06:18:32.510107 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000027 (ops 130-134)
I20260812 06:18:32.510164 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000028 (ops 135-139)
I20260812 06:18:32.510222 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000029 (ops 140-144)
I20260812 06:18:32.510267 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000030 (ops 145-148)
I20260812 06:18:32.510304 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000031 (ops 149-153)
I20260812 06:18:32.510344 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000032 (ops 154-158)
I20260812 06:18:32.510385 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000033 (ops 159-163)
I20260812 06:18:32.510422 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000034 (ops 164-168)
I20260812 06:18:32.510461 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000035 (ops 169-173)
I20260812 06:18:32.510500 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000036 (ops 174-178)
I20260812 06:18:32.510557 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000037 (ops 179-183)
I20260812 06:18:32.510596 11826 log.cc:1079] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/3d70e944449945bbb035df992b955ef3/wal-000000038 (ops 184-188)
I20260812 06:18:32.536271 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: LogGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:32.536708 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3): 473 bytes on disk
I20260812 06:18:32.537153 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: UndoDeltaBlockGCOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.537662 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:32.560725 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.023s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.561164 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=2.188937
I20260812 06:18:32.571239 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.571656 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3): perf score=1.000000
I20260812 06:18:32.813846 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: MajorDeltaCompactionOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.242s	user 0.147s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":6836,"dirs.run_cpu_time_us":1309,"dirs.run_wall_time_us":8881,"lbm_read_time_us":16341,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40552,"lbm_writes_lt_1ms":743,"mutex_wait_us":3676,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":39424,"thread_start_us":701,"threads_started":1,"update_count":3500}
I20260812 06:18:32.814512 11919 maintenance_manager.cc:419] P 3f717a6d59ce40e49874ee9034b0ad92: Scheduling FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3): perf score=18.063937
I20260812 06:18:32.819881 11662 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.867s	user 1.817s	sys 0.169s
I20260812 06:18:32.868022 11662 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.048s	user 0.003s	sys 0.000s
I20260812 06:18:32.868654 11662 tablet_server.cc:179] TabletServer@127.11.99.129:0 shutting down...
I20260812 06:18:32.882015 11826 maintenance_manager.cc:643] P 3f717a6d59ce40e49874ee9034b0ad92: FlushDeltaMemStoresOp(3d70e944449945bbb035df992b955ef3) complete. Timing: real 0.067s	user 0.036s	sys 0.027s Metrics: {"bytes_written":19691835,"delete_count":0,"lbm_write_time_us":30411,"lbm_writes_lt_1ms":483,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2400}
I20260812 06:18:32.882577 11662 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:32.882984 11662 tablet_replica.cc:333] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92: stopping tablet replica
I20260812 06:18:32.883229 11662 raft_consensus.cc:2243] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.883459 11662 raft_consensus.cc:2272] T 3d70e944449945bbb035df992b955ef3 P 3f717a6d59ce40e49874ee9034b0ad92 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.898453 11662 tablet_server.cc:196] TabletServer@127.11.99.129:0 shutdown complete.
I20260812 06:18:32.903056 11662 master.cc:562] Master@127.11.99.190:38817 shutting down...
I20260812 06:18:32.907153 11662 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.907341 11662 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.907420 11662 tablet_replica.cc:333] T 00000000000000000000000000000000 P 450e241b5ac3434e9769ed048bb78c25: stopping tablet replica
I20260812 06:18:32.919585 11662 master.cc:584] Master@127.11.99.190:38817 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5349 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:33.017306 11662 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.99.190:41537
I20260812 06:18:33.017747 11662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.019892 11977 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.019883 11978 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.020005 11982 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:33.020090 11662 server_base.cc:1061] running on GCE node
I20260812 06:18:33.020254 11662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.020314 11662 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:33.020354 11662 hybrid_clock.cc:648] HybridClock initialized: now 1786515513020353 us; error 0 us; skew 500 ppm
I20260812 06:18:33.021195 11662 webserver.cc:533] Webserver started at http://127.11.99.190:34775/ using document root <none> and password file <none>
I20260812 06:18:33.021376 11662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.021450 11662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.021528 11662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.021982 11662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/master-0-root/instance:
uuid: "d6789f8a2e464938ad8fd1781ba76139"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-w4v5"
I20260812 06:18:33.023670 11662 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:33.024637 11994 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.024933 11662 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.025027 11662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/master-0-root
uuid: "d6789f8a2e464938ad8fd1781ba76139"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-w4v5"
I20260812 06:18:33.025118 11662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:33.032289 11662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.032660 11662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.036989 11662 rpc_server.cc:307] RPC server started. Bound to: 127.11.99.190:41537
I20260812 06:18:33.040030 12072 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.99.190:41537 every 8 connection(s)
I20260812 06:18:33.045523 12076 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.052166 12076 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139: Bootstrap starting.
I20260812 06:18:33.052951 12076 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.054009 12076 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139: No bootstrap required, opened a new log
I20260812 06:18:33.054363 12076 raft_consensus.cc:359] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6789f8a2e464938ad8fd1781ba76139" member_type: VOTER }
I20260812 06:18:33.054450 12076 raft_consensus.cc:385] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.054473 12076 raft_consensus.cc:740] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d6789f8a2e464938ad8fd1781ba76139, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.054576 12076 consensus_queue.cc:260] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [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: "d6789f8a2e464938ad8fd1781ba76139" member_type: VOTER }
I20260812 06:18:33.054636 12076 raft_consensus.cc:399] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.054695 12076 raft_consensus.cc:493] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.054790 12076 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.055615 12076 raft_consensus.cc:515] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6789f8a2e464938ad8fd1781ba76139" member_type: VOTER }
I20260812 06:18:33.055744 12076 leader_election.cc:304] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [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: d6789f8a2e464938ad8fd1781ba76139; no voters: 
I20260812 06:18:33.056003 12076 leader_election.cc:290] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.056187 12084 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.056373 12084 raft_consensus.cc:697] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 1 LEADER]: Becoming Leader. State: Replica: d6789f8a2e464938ad8fd1781ba76139, State: Running, Role: LEADER
I20260812 06:18:33.056510 12076 sys_catalog.cc:565] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:33.056535 12084 consensus_queue.cc:237] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [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: "d6789f8a2e464938ad8fd1781ba76139" member_type: VOTER }
I20260812 06:18:33.056981 12086 sys_catalog.cc:455] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d6789f8a2e464938ad8fd1781ba76139" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6789f8a2e464938ad8fd1781ba76139" member_type: VOTER } }
I20260812 06:18:33.057036 12089 sys_catalog.cc:455] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d6789f8a2e464938ad8fd1781ba76139. Latest consensus state: current_term: 1 leader_uuid: "d6789f8a2e464938ad8fd1781ba76139" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6789f8a2e464938ad8fd1781ba76139" member_type: VOTER } }
I20260812 06:18:33.057127 12086 sys_catalog.cc:458] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.057206 12089 sys_catalog.cc:458] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.057722 12095 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:33.058786 12095 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:33.059041 11662 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:33.060839 12095 catalog_manager.cc:1383] Generated new cluster ID: fcb2be7324a74f1991ed7f737497c4b1
I20260812 06:18:33.060900 12095 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:33.068238 12095 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:33.068730 12095 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:33.074895 12095 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139: Generated new TSK 0
I20260812 06:18:33.075042 12095 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:33.091720 11662 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.093766 12114 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.093767 12124 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.093767 12120 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:33.093918 11662 server_base.cc:1061] running on GCE node
I20260812 06:18:33.094177 11662 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.094208 11662 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:33.094223 11662 hybrid_clock.cc:648] HybridClock initialized: now 1786515513094223 us; error 0 us; skew 500 ppm
I20260812 06:18:33.095067 11662 webserver.cc:533] Webserver started at http://127.11.99.129:46089/ using document root <none> and password file <none>
I20260812 06:18:33.095276 11662 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.095322 11662 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.095387 11662 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.095736 11662 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/instance:
uuid: "cd897dfdd3274983840c648c4ec28307"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-w4v5"
I20260812 06:18:33.097226 11662 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:33.098141 12134 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.098410 11662 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.098502 11662 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root
uuid: "cd897dfdd3274983840c648c4ec28307"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-w4v5"
I20260812 06:18:33.098591 11662 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:33.118106 11662 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.118526 11662 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.118875 11662 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:33.119395 11662 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:33.119459 11662 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.119511 11662 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:33.119561 11662 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.124004 11662 rpc_server.cc:307] RPC server started. Bound to: 127.11.99.129:36721
I20260812 06:18:33.124722 12238 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.99.129:36721 every 8 connection(s)
I20260812 06:18:33.134336 12242 heartbeater.cc:344] Connected to a master server at 127.11.99.190:41537
I20260812 06:18:33.134459 12242 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:33.134747 12242 heartbeater.cc:507] Master 127.11.99.190:41537 requested a full tablet report, sending...
I20260812 06:18:33.135560 12017 ts_manager.cc:194] Registered new tserver with Master: cd897dfdd3274983840c648c4ec28307 (127.11.99.129:36721)
I20260812 06:18:33.136324 12017 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39024
I20260812 06:18:33.136336 11662 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011531951s
I20260812 06:18:33.143262 12017 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39036:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:33.152051 12185 tablet_service.cc:1511] Processing CreateTablet for tablet 5b0644471c4e4f92bbdb91f6646ef4fd (DEFAULT_TABLE table=heavy-update-compaction-test [id=3d0ebd4afa71496583e7cf4fa98f52c5]), partition=
I20260812 06:18:33.152350 12185 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5b0644471c4e4f92bbdb91f6646ef4fd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.154551 12260 tablet_bootstrap.cc:492] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Bootstrap starting.
I20260812 06:18:33.155465 12260 tablet_bootstrap.cc:654] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.156597 12260 tablet_bootstrap.cc:492] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: No bootstrap required, opened a new log
I20260812 06:18:33.156678 12260 ts_tablet_manager.cc:1403] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:33.157259 12260 raft_consensus.cc:359] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd897dfdd3274983840c648c4ec28307" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 36721 } }
I20260812 06:18:33.157373 12260 raft_consensus.cc:385] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.157410 12260 raft_consensus.cc:740] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cd897dfdd3274983840c648c4ec28307, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.157558 12260 consensus_queue.cc:260] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [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: "cd897dfdd3274983840c648c4ec28307" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 36721 } }
I20260812 06:18:33.157665 12260 raft_consensus.cc:399] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.157691 12260 raft_consensus.cc:493] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.157722 12260 raft_consensus.cc:3060] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.158514 12260 raft_consensus.cc:515] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd897dfdd3274983840c648c4ec28307" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 36721 } }
I20260812 06:18:33.158649 12260 leader_election.cc:304] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [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: cd897dfdd3274983840c648c4ec28307; no voters: 
I20260812 06:18:33.158806 12260 leader_election.cc:290] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.158931 12265 raft_consensus.cc:2804] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.159154 12260 ts_tablet_manager.cc:1434] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:33.159196 12242 heartbeater.cc:499] Master 127.11.99.190:41537 was elected leader, sending a full tablet report...
I20260812 06:18:33.159207 12265 raft_consensus.cc:697] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 1 LEADER]: Becoming Leader. State: Replica: cd897dfdd3274983840c648c4ec28307, State: Running, Role: LEADER
I20260812 06:18:33.159421 12265 consensus_queue.cc:237] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [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: "cd897dfdd3274983840c648c4ec28307" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 36721 } }
I20260812 06:18:33.160866 12017 catalog_manager.cc:5719] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 reported cstate change: term changed from 0 to 1, leader changed from <none> to cd897dfdd3274983840c648c4ec28307 (127.11.99.129). New cstate: current_term: 1 leader_uuid: "cd897dfdd3274983840c648c4ec28307" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd897dfdd3274983840c648c4ec28307" member_type: VOTER last_known_addr { host: "127.11.99.129" port: 36721 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:33.220371 11662 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.004s
I20260812 06:18:33.375406 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=19.054940
I20260812 06:18:33.537415 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.162s	user 0.118s	sys 0.041s Metrics: {"bytes_written":13497198,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":861,"drs_written":1,"lbm_read_time_us":132,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42567,"lbm_writes_lt_1ms":786,"mutex_wait_us":799,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1645}
I20260812 06:18:33.538070 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): free 20743880 bytes of WAL
I20260812 06:18:33.538314 12142 log_reader.cc:385] T 5b0644471c4e4f92bbdb91f6646ef4fd: removed 2 log segments from log reader
I20260812 06:18:33.538378 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000001 (ops 1-6)
I20260812 06:18:33.538463 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000002 (ops 7-11)
I20260812 06:18:33.543284 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:33.543596 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): 16411391 bytes on disk
I20260812 06:18:33.543943 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.544377 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.196750
I20260812 06:18:33.558934 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.014s	user 0.004s	sys 0.002s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":2839,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:18:33.559425 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:33.569373 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.010s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.569721 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:33.735705 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.166s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774787,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":789,"lbm_read_time_us":11114,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30391,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":332,"threads_started":5,"update_count":2500}
I20260812 06:18:33.736374 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:33.784119 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.048s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22805,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.784525 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:33.798403 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.799118 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:33.965509 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.166s	user 0.123s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":11511,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28852,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:18:33.966145 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:34.031535 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.065s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27440,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.032145 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:34.043881 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.044368 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:34.218039 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.173s	user 0.115s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":12123,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29118,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:18:34.218713 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:34.287446 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.068s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":36547,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.287871 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:34.298641 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.299263 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:34.482384 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.182s	user 0.118s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3874,"lbm_read_time_us":12669,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29384,"lbm_writes_lt_1ms":543,"mutex_wait_us":3598,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:34.482949 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:34.540884 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.058s	user 0.020s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19585,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.541443 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:34.558069 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.558607 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:34.740842 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.182s	user 0.138s	sys 0.040s 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":156,"lbm_read_time_us":13217,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28377,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:18:34.741634 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:34.803879 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.062s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.804409 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:34.815332 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.815785 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:34.863336 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.047s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1334,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1479,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:34.864003 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): free 116849511 bytes of WAL
I20260812 06:18:34.864239 12142 log_reader.cc:385] T 5b0644471c4e4f92bbdb91f6646ef4fd: removed 12 log segments from log reader
I20260812 06:18:34.864285 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000003 (ops 12-16)
I20260812 06:18:34.864339 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000004 (ops 17-20)
I20260812 06:18:34.864385 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000005 (ops 21-25)
I20260812 06:18:34.864414 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000006 (ops 26-30)
I20260812 06:18:34.864454 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000007 (ops 31-34)
I20260812 06:18:34.864492 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000008 (ops 35-39)
I20260812 06:18:34.864530 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000009 (ops 40-44)
I20260812 06:18:34.864569 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000010 (ops 45-48)
I20260812 06:18:34.864607 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000011 (ops 49-53)
I20260812 06:18:34.864650 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000012 (ops 54-58)
I20260812 06:18:34.864692 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000013 (ops 59-63)
I20260812 06:18:34.864730 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000014 (ops 64-68)
I20260812 06:18:34.890000 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:34.890415 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): 472 bytes on disk
I20260812 06:18:34.890909 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.891440 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=3.181125
I20260812 06:18:34.911762 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.020s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5635,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:34.912250 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:34.921577 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3498,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.922049 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:35.155545 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.233s	user 0.162s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":702,"lbm_read_time_us":16449,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37728,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":45056,"thread_start_us":107,"threads_started":1,"update_count":3500}
I20260812 06:18:35.156342 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=16.079562
I20260812 06:18:35.223858 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.067s	user 0.040s	sys 0.021s Metrics: {"bytes_written":17640627,"delete_count":0,"lbm_write_time_us":26442,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2150}
I20260812 06:18:35.224332 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=5.165500
I20260812 06:18:35.242568 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":6974360,"delete_count":0,"lbm_write_time_us":7506,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:18:35.243113 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:35.456830 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.214s	user 0.150s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":15433,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32667,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":3000}
I20260812 06:18:35.457653 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=18.063937
I20260812 06:18:35.531003 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.073s	user 0.028s	sys 0.029s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27664,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.531664 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:35.546964 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.547494 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:35.750833 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.203s	user 0.117s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":755,"lbm_read_time_us":14194,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34609,"lbm_writes_lt_1ms":643,"mutex_wait_us":306,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3000}
I20260812 06:18:35.752262 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=16.079562
I20260812 06:18:35.818194 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.066s	user 0.024s	sys 0.024s Metrics: {"bytes_written":17763699,"delete_count":0,"lbm_write_time_us":22608,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:18:35.818825 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=5.165500
I20260812 06:18:35.844880 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.026s	user 0.011s	sys 0.007s Metrics: {"bytes_written":6851288,"delete_count":0,"lbm_write_time_us":8688,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:18:35.845404 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:36.050714 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.205s	user 0.147s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":13428,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32953,"lbm_writes_lt_1ms":643,"mutex_wait_us":87,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:18:36.051437 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=18.063937
I20260812 06:18:36.106060 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.054s	user 0.031s	sys 0.019s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":23871,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.106655 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:36.279436 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.173s	user 0.096s	sys 0.076s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774573,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":933,"lbm_read_time_us":12163,"lbm_reads_lt_1ms":563,"lbm_write_time_us":28854,"lbm_writes_lt_1ms":543,"mutex_wait_us":358,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:18:36.280290 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:36.340904 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.060s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22405,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.341502 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:36.359768 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.360525 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:36.396343 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.036s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1301,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1384,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:36.396999 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): free 124257256 bytes of WAL
I20260812 06:18:36.397238 12142 log_reader.cc:385] T 5b0644471c4e4f92bbdb91f6646ef4fd: removed 12 log segments from log reader
I20260812 06:18:36.397311 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000015 (ops 69-73)
I20260812 06:18:36.397367 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000016 (ops 74-78)
I20260812 06:18:36.397423 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000017 (ops 79-83)
I20260812 06:18:36.397468 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000018 (ops 84-88)
I20260812 06:18:36.397506 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000019 (ops 89-93)
I20260812 06:18:36.397630 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000020 (ops 94-98)
I20260812 06:18:36.397682 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000021 (ops 99-102)
I20260812 06:18:36.397725 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000022 (ops 103-107)
I20260812 06:18:36.397766 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000023 (ops 108-112)
I20260812 06:18:36.397811 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000024 (ops 113-117)
I20260812 06:18:36.397853 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000025 (ops 118-122)
I20260812 06:18:36.397893 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000026 (ops 123-127)
I20260812 06:18:36.424281 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:36.424814 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): 471 bytes on disk
I20260812 06:18:36.425239 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.426823 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=3.181125
I20260812 06:18:36.442247 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4389828,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:18:36.442675 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:36.452329 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3815483,"delete_count":0,"lbm_write_time_us":3623,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:36.452776 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:36.680058 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.227s	user 0.143s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":544,"lbm_read_time_us":14963,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40948,"lbm_writes_lt_1ms":743,"mutex_wait_us":36,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:18:36.680824 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=18.063937
I20260812 06:18:36.745371 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.064s	user 0.035s	sys 0.027s Metrics: {"bytes_written":20512313,"delete_count":0,"lbm_write_time_us":28233,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.745945 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:36.773486 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.773998 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:36.784288 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.784736 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:36.972447 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.188s	user 0.134s	sys 0.047s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979630,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":982,"lbm_read_time_us":12966,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37800,"lbm_writes_lt_1ms":743,"mutex_wait_us":522,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3500}
I20260812 06:18:36.973096 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=15.087375
I20260812 06:18:37.043875 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.071s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":26301,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:18:37.044363 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=6.157687
I20260812 06:18:37.068841 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.024s	user 0.017s	sys 0.004s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":10082,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:37.069425 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:37.245151 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.176s	user 0.140s	sys 0.035s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":114,"lbm_read_time_us":11362,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35945,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:18:37.245836 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:37.297861 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.052s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22944,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.298449 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=3.181125
I20260812 06:18:37.323382 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.025s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7194,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.323840 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:37.336952 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5075,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.337472 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:37.497615 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.160s	user 0.136s	sys 0.023s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1046,"lbm_read_time_us":11378,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31822,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:18:37.498445 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:37.549516 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.051s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22826,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.550067 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=2.188937
I20260812 06:18:37.567516 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.568058 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:37.726984 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.159s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":748,"lbm_read_time_us":8647,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32891,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:18:37.727864 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:37.772635 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.045s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19559,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.773334 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:37.804553 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushMRSOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1211,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1507,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:37.805616 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): free 129320783 bytes of WAL
I20260812 06:18:37.805943 12142 log_reader.cc:385] T 5b0644471c4e4f92bbdb91f6646ef4fd: removed 13 log segments from log reader
I20260812 06:18:37.806074 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000027 (ops 128-132)
I20260812 06:18:37.806186 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000028 (ops 133-136)
I20260812 06:18:37.806288 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000029 (ops 137-141)
I20260812 06:18:37.806406 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000030 (ops 142-146)
I20260812 06:18:37.806516 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000031 (ops 147-151)
I20260812 06:18:37.806668 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000032 (ops 152-156)
I20260812 06:18:37.806782 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000033 (ops 157-161)
I20260812 06:18:37.806879 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000034 (ops 162-166)
I20260812 06:18:37.806947 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000035 (ops 167-170)
I20260812 06:18:37.807009 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000036 (ops 171-175)
I20260812 06:18:37.807049 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000037 (ops 176-180)
I20260812 06:18:37.807097 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000038 (ops 181-185)
I20260812 06:18:37.807157 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000039 (ops 186-190)
I20260812 06:18:37.835983 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.030s	user 0.002s	sys 0.026s Metrics: {}
I20260812 06:18:37.836572 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): 483 bytes on disk
I20260812 06:18:37.837096 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: UndoDeltaBlockGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.837705 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=5.165500
I20260812 06:18:37.856570 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.019s	user 0.008s	sys 0.009s Metrics: {"bytes_written":6933327,"delete_count":0,"lbm_write_time_us":7795,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:18:37.857268 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:37.864604 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1271927,"delete_count":0,"lbm_write_time_us":2279,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:18:37.865031 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd): free 11564893 bytes of WAL
I20260812 06:18:37.865242 12142 log_reader.cc:385] T 5b0644471c4e4f92bbdb91f6646ef4fd: removed 1 log segments from log reader
I20260812 06:18:37.865288 12142 log.cc:1079] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: Deleting log segment in path: /tmp/dist-test-taskj8Txge/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507657956-11662-0/minicluster-data/ts-0-root/wals/5b0644471c4e4f92bbdb91f6646ef4fd/wal-000000040 (ops 191-194)
I20260812 06:18:37.867671 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: LogGCOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:37.867959 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:38.029325 11662 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.809s	user 1.800s	sys 0.168s
I20260812 06:18:38.054826 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.187s	user 0.102s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877151,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":13907,"lbm_reads_lt_1ms":669,"lbm_write_time_us":30474,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":3000}
I20260812 06:18:38.055382 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=14.095187
I20260812 06:18:38.088299 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: FlushDeltaMemStoresOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.033s	user 0.010s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16231,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.088824 12244 maintenance_manager.cc:419] P cd897dfdd3274983840c648c4ec28307: Scheduling MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd): perf score=1.000000
I20260812 06:18:38.122838 11662 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.001s	sys 0.000s
I20260812 06:18:38.123435 11662 tablet_server.cc:179] TabletServer@127.11.99.129:0 shutting down...
I20260812 06:18:38.213012 12142 maintenance_manager.cc:643] P cd897dfdd3274983840c648c4ec28307: MajorDeltaCompactionOp(5b0644471c4e4f92bbdb91f6646ef4fd) complete. Timing: real 0.124s	user 0.086s	sys 0.036s 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":250,"lbm_read_time_us":9803,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24284,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:18:38.213784 11662 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.214026 11662 tablet_replica.cc:333] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307: stopping tablet replica
I20260812 06:18:38.214179 11662 raft_consensus.cc:2243] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.214363 11662 raft_consensus.cc:2272] T 5b0644471c4e4f92bbdb91f6646ef4fd P cd897dfdd3274983840c648c4ec28307 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.228287 11662 tablet_server.cc:196] TabletServer@127.11.99.129:0 shutdown complete.
I20260812 06:18:38.252363 11662 master.cc:562] Master@127.11.99.190:41537 shutting down...
I20260812 06:18:38.255728 11662 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.255914 11662 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.256011 11662 tablet_replica.cc:333] T 00000000000000000000000000000000 P d6789f8a2e464938ad8fd1781ba76139: stopping tablet replica
I20260812 06:18:38.268352 11662 master.cc:584] Master@127.11.99.190:41537 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5333 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10684 ms total)

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