[==========] 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:43.009968 16538 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.38.190:45477
I20260812 06:18:43.010988 16538 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:43.011652 16538 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.018198 16543 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:43.018271 16538 server_base.cc:1061] running on GCE node
W20260812 06:18:43.018181 16548 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:43.018494 16545 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:43.018973 16538 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.019125 16538 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:43.019209 16538 hybrid_clock.cc:648] HybridClock initialized: now 1786515523019192 us; error 0 us; skew 500 ppm
I20260812 06:18:43.020968 16538 webserver.cc:533] Webserver started at http://127.16.38.190:45783/ using document root <none> and password file <none>
I20260812 06:18:43.021508 16538 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.021562 16538 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.021840 16538 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.023496 16538 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/master-0-root/instance:
uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-1xrh"
I20260812 06:18:43.026907 16538 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:18:43.028962 16554 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:43.029939 16538 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:43.030069 16538 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/master-0-root
uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-1xrh"
I20260812 06:18:43.030169 16538 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-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:43.047720 16538 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.048295 16538 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:43.048470 16538 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.055940 16538 rpc_server.cc:307] RPC server started. Bound to: 127.16.38.190:45477
I20260812 06:18:43.055956 16611 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.38.190:45477 every 8 connection(s)
I20260812 06:18:43.058115 16612 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:43.063416 16612 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976: Bootstrap starting.
I20260812 06:18:43.065759 16612 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.066640 16612 log.cc:826] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:43.068284 16612 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976: No bootstrap required, opened a new log
I20260812 06:18:43.070942 16612 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976" member_type: VOTER }
I20260812 06:18:43.071100 16612 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.071157 16612 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3205ecf1ff4d49d4aa3c0ea9cf63d976, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.071785 16612 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [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: "3205ecf1ff4d49d4aa3c0ea9cf63d976" member_type: VOTER }
I20260812 06:18:43.071931 16612 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.072034 16612 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.072202 16612 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.073015 16612 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976" member_type: VOTER }
I20260812 06:18:43.073460 16612 leader_election.cc:304] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [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: 3205ecf1ff4d49d4aa3c0ea9cf63d976; no voters: 
I20260812 06:18:43.073808 16612 leader_election.cc:290] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.073951 16616 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.074218 16616 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 1 LEADER]: Becoming Leader. State: Replica: 3205ecf1ff4d49d4aa3c0ea9cf63d976, State: Running, Role: LEADER
I20260812 06:18:43.074644 16616 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [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: "3205ecf1ff4d49d4aa3c0ea9cf63d976" member_type: VOTER }
I20260812 06:18:43.074875 16612 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.076646 16618 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976" member_type: VOTER } }
I20260812 06:18:43.076696 16619 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3205ecf1ff4d49d4aa3c0ea9cf63d976. Latest consensus state: current_term: 1 leader_uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3205ecf1ff4d49d4aa3c0ea9cf63d976" member_type: VOTER } }
I20260812 06:18:43.076773 16618 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.076805 16619 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.077145 16630 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.077328 16538 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.079545 16630 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.084358 16630 catalog_manager.cc:1383] Generated new cluster ID: 134d6224a49d4cc8900e9d10ef98b3ca
I20260812 06:18:43.084432 16630 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:43.098416 16630 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:43.099262 16630 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:43.106541 16630 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976: Generated new TSK 0
I20260812 06:18:43.107168 16630 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:43.109706 16538 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.112151 16638 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:43.112293 16639 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:43.112201 16642 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:43.112591 16538 server_base.cc:1061] running on GCE node
I20260812 06:18:43.112766 16538 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.112804 16538 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:43.112820 16538 hybrid_clock.cc:648] HybridClock initialized: now 1786515523112820 us; error 0 us; skew 500 ppm
I20260812 06:18:43.113725 16538 webserver.cc:533] Webserver started at http://127.16.38.129:41363/ using document root <none> and password file <none>
I20260812 06:18:43.113911 16538 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.113960 16538 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.114063 16538 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.114473 16538 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/instance:
uuid: "33153970800c497392a863517af5acd9"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-1xrh"
I20260812 06:18:43.116422 16538 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:43.117461 16648 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:43.117729 16538 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:43.117795 16538 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root
uuid: "33153970800c497392a863517af5acd9"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-1xrh"
I20260812 06:18:43.117882 16538 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-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:43.129725 16538 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.130177 16538 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.130651 16538 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:43.131776 16538 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:43.131834 16538 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.131909 16538 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:43.131961 16538 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.138526 16538 rpc_server.cc:307] RPC server started. Bound to: 127.16.38.129:41565
I20260812 06:18:43.138563 16717 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.38.129:41565 every 8 connection(s)
I20260812 06:18:43.153556 16719 heartbeater.cc:344] Connected to a master server at 127.16.38.190:45477
I20260812 06:18:43.153839 16719 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:43.154273 16719 heartbeater.cc:507] Master 127.16.38.190:45477 requested a full tablet report, sending...
I20260812 06:18:43.155730 16573 ts_manager.cc:194] Registered new tserver with Master: 33153970800c497392a863517af5acd9 (127.16.38.129:41565)
I20260812 06:18:43.155974 16538 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01679498s
I20260812 06:18:43.157029 16573 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49476
I20260812 06:18:43.165391 16573 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49478:
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:43.179404 16677 tablet_service.cc:1511] Processing CreateTablet for tablet b56b1730feed4a989951f4a5c1c85ad3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ef9029eb5db04f93991c48e9680b6948]), partition=
I20260812 06:18:43.179858 16677 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b56b1730feed4a989951f4a5c1c85ad3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.182564 16733 tablet_bootstrap.cc:492] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Bootstrap starting.
I20260812 06:18:43.183835 16733 tablet_bootstrap.cc:654] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.184973 16733 tablet_bootstrap.cc:492] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: No bootstrap required, opened a new log
I20260812 06:18:43.185092 16733 ts_tablet_manager.cc:1403] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:43.185547 16733 raft_consensus.cc:359] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33153970800c497392a863517af5acd9" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 41565 } }
I20260812 06:18:43.185672 16733 raft_consensus.cc:385] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.185720 16733 raft_consensus.cc:740] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 33153970800c497392a863517af5acd9, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.185861 16733 consensus_queue.cc:260] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [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: "33153970800c497392a863517af5acd9" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 41565 } }
I20260812 06:18:43.185979 16733 raft_consensus.cc:399] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.186028 16733 raft_consensus.cc:493] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.186082 16733 raft_consensus.cc:3060] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.187000 16733 raft_consensus.cc:515] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33153970800c497392a863517af5acd9" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 41565 } }
I20260812 06:18:43.187194 16733 leader_election.cc:304] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [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: 33153970800c497392a863517af5acd9; no voters: 
I20260812 06:18:43.187458 16733 leader_election.cc:290] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.187570 16736 raft_consensus.cc:2804] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.187819 16733 ts_tablet_manager.cc:1434] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:18:43.187875 16736 raft_consensus.cc:697] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 1 LEADER]: Becoming Leader. State: Replica: 33153970800c497392a863517af5acd9, State: Running, Role: LEADER
I20260812 06:18:43.188066 16719 heartbeater.cc:499] Master 127.16.38.190:45477 was elected leader, sending a full tablet report...
I20260812 06:18:43.188043 16736 consensus_queue.cc:237] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [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: "33153970800c497392a863517af5acd9" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 41565 } }
I20260812 06:18:43.190943 16573 catalog_manager.cc:5719] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 33153970800c497392a863517af5acd9 (127.16.38.129). New cstate: current_term: 1 leader_uuid: "33153970800c497392a863517af5acd9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33153970800c497392a863517af5acd9" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 41565 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:43.259021 16538 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.018s	sys 0.008s
I20260812 06:18:43.389703 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=15.086190
I20260812 06:18:43.579686 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.190s	user 0.159s	sys 0.029s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":709,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1033,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48038,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":121,"threads_started":1,"update_count":1500}
I20260812 06:18:43.581038 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling LogGCOp(b56b1730feed4a989951f4a5c1c85ad3): free 20743880 bytes of WAL
I20260812 06:18:43.581374 16653 log_reader.cc:385] T b56b1730feed4a989951f4a5c1c85ad3: removed 2 log segments from log reader
I20260812 06:18:43.581451 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000001 (ops 1-6)
I20260812 06:18:43.581509 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000002 (ops 7-11)
I20260812 06:18:43.587929 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: LogGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:18:43.588622 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=3.181125
I20260812 06:18:43.614879 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.026s	user 0.003s	sys 0.019s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7306,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.615399 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3): 16411393 bytes on disk
I20260812 06:18:43.616089 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.616545 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:43.629940 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5184,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.630359 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:43.796263 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.166s	user 0.103s	sys 0.063s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":980,"lbm_read_time_us":13627,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28802,"lbm_writes_lt_1ms":543,"mutex_wait_us":446,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"thread_start_us":375,"threads_started":5,"update_count":2500}
I20260812 06:18:43.797268 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=10.126437
I20260812 06:18:43.839619 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.042s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18816,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.840132 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:43.850629 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.851186 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:43.983078 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.132s	user 0.103s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":10079,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24868,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.983589 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=10.126437
I20260812 06:18:44.028649 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.045s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":17364,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.029093 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:44.040536 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.041043 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:44.171758 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.131s	user 0.105s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":10380,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25364,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:44.172235 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=10.126437
I20260812 06:18:44.215651 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.043s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15914,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.216150 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:44.227833 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.228325 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:44.363551 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.135s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":9637,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25682,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:44.364317 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=11.118625
I20260812 06:18:44.424453 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.060s	user 0.031s	sys 0.027s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":22841,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.424928 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:44.438504 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.438947 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:44.452656 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.453088 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:44.650086 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.197s	user 0.134s	sys 0.052s 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":658,"lbm_read_time_us":14341,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35566,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:44.650727 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:44.713585 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.063s	user 0.032s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19787,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.714135 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:44.730978 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.731532 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:44.898793 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.167s	user 0.142s	sys 0.024s 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":632,"lbm_read_time_us":13687,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29121,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:44.899434 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=10.126437
I20260812 06:18:44.936421 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.037s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16014,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.936949 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:44.952617 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.953342 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:44.995015 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.041s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1464,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2241,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:44.995951 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling LogGCOp(b56b1730feed4a989951f4a5c1c85ad3): free 121006431 bytes of WAL
I20260812 06:18:44.996273 16653 log_reader.cc:385] T b56b1730feed4a989951f4a5c1c85ad3: removed 12 log segments from log reader
I20260812 06:18:44.996347 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000003 (ops 12-16)
I20260812 06:18:44.996397 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000004 (ops 17-21)
I20260812 06:18:44.996441 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000005 (ops 22-26)
I20260812 06:18:44.996474 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000006 (ops 27-30)
I20260812 06:18:44.996516 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000007 (ops 31-35)
I20260812 06:18:44.996551 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000008 (ops 36-40)
I20260812 06:18:44.996592 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000009 (ops 41-45)
I20260812 06:18:44.996631 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000010 (ops 46-50)
I20260812 06:18:44.996673 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000011 (ops 51-55)
I20260812 06:18:44.996716 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000012 (ops 56-60)
I20260812 06:18:44.996758 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000013 (ops 61-65)
I20260812 06:18:44.996798 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000014 (ops 66-70)
I20260812 06:18:45.029183 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: LogGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:45.029597 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=3.181125
I20260812 06:18:45.052966 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.023s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7273,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.053438 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling LogGCOp(b56b1730feed4a989951f4a5c1c85ad3): free 12017927 bytes of WAL
I20260812 06:18:45.053660 16653 log_reader.cc:385] T b56b1730feed4a989951f4a5c1c85ad3: removed 1 log segments from log reader
I20260812 06:18:45.053742 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000015 (ops 71-75)
I20260812 06:18:45.057025 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: LogGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:45.057322 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3): 493 bytes on disk
I20260812 06:18:45.057811 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.058252 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:45.068640 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3740,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.069182 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:45.266794 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.197s	user 0.120s	sys 0.077s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1080,"lbm_read_time_us":14689,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34960,"lbm_writes_lt_1ms":643,"mutex_wait_us":319,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:45.267352 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:45.336148 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.069s	user 0.037s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26114,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.336640 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:45.347366 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.348024 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:45.528126 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.180s	user 0.124s	sys 0.056s 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":202,"lbm_read_time_us":13490,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32592,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:18:45.528698 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:45.589493 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.061s	user 0.028s	sys 0.030s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22671,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.589970 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:45.603554 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.604267 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:45.793845 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.189s	user 0.135s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":11753,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33758,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:45.794543 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:45.855758 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.061s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20319,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.856323 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:45.872700 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.873212 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:46.069497 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.196s	user 0.127s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1384,"lbm_read_time_us":13605,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32099,"lbm_writes_lt_1ms":543,"mutex_wait_us":368,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:46.070005 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:46.117563 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.047s	user 0.017s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20587,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.118012 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:46.129962 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.130451 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:46.311546 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.181s	user 0.130s	sys 0.048s 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":158,"lbm_read_time_us":10126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32215,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:46.312143 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:46.363584 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.051s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23019,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.364104 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:46.390264 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":5290,"lbm_writes_lt_1ms":106,"mutex_wait_us":171,"reinsert_count":0,"update_count":515}
I20260812 06:18:46.390740 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:46.410794 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.020s	user 0.001s	sys 0.015s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3942,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:46.411396 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:46.620625 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.209s	user 0.124s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877222,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":996,"lbm_read_time_us":15788,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35402,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:46.621236 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:46.689682 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.068s	user 0.030s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21364,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.690214 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:46.701035 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.701567 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:46.746596 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.045s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1316415,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1388,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2887,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:46.747449 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling LogGCOp(b56b1730feed4a989951f4a5c1c85ad3): free 124710336 bytes of WAL
I20260812 06:18:46.747695 16653 log_reader.cc:385] T b56b1730feed4a989951f4a5c1c85ad3: removed 12 log segments from log reader
I20260812 06:18:46.747745 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000016 (ops 76-80)
I20260812 06:18:46.747802 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000017 (ops 81-85)
I20260812 06:18:46.747860 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000018 (ops 86-90)
I20260812 06:18:46.747929 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000019 (ops 91-95)
I20260812 06:18:46.747972 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000020 (ops 96-100)
I20260812 06:18:46.748039 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000021 (ops 101-105)
I20260812 06:18:46.748086 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000022 (ops 106-110)
I20260812 06:18:46.748129 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000023 (ops 111-115)
I20260812 06:18:46.748173 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000024 (ops 116-120)
I20260812 06:18:46.748216 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000025 (ops 121-125)
I20260812 06:18:46.748265 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000026 (ops 126-130)
I20260812 06:18:46.748310 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000027 (ops 131-135)
I20260812 06:18:46.780571 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: LogGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.033s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:46.781132 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=3.181125
I20260812 06:18:46.795298 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4759050,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 06:18:46.795802 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3): 492 bytes on disk
I20260812 06:18:46.796268 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3) 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:46.796823 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:46.808941 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:18:46.809422 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:47.077947 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.268s	user 0.170s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":812,"dirs.run_cpu_time_us":1931,"dirs.run_wall_time_us":12134,"lbm_read_time_us":17976,"lbm_reads_lt_1ms":774,"lbm_write_time_us":47723,"lbm_writes_lt_1ms":743,"mutex_wait_us":397,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":3500}
I20260812 06:18:47.078552 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=18.063937
I20260812 06:18:47.137990 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.059s	user 0.033s	sys 0.023s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27034,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.138484 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:47.149201 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.149855 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:47.362332 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.212s	user 0.163s	sys 0.045s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":640,"lbm_read_time_us":15217,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37814,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:18:47.363339 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=18.063937
I20260812 06:18:47.423918 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.060s	user 0.034s	sys 0.025s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27405,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.424471 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:47.442047 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.442505 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:47.617764 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.175s	user 0.135s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":62,"lbm_read_time_us":12122,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36815,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:18:47.618564 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:47.663241 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.044s	user 0.040s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19378,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.663838 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:47.680367 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.680802 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:47.845620 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.165s	user 0.088s	sys 0.074s 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":1140,"lbm_read_time_us":11514,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30264,"lbm_writes_lt_1ms":543,"mutex_wait_us":445,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:47.846205 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=14.095187
I20260812 06:18:47.897372 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.051s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23415,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.897835 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:48.052286 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.154s	user 0.110s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":151,"lbm_read_time_us":11798,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25510,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:48.053092 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=11.118625
I20260812 06:18:48.092048 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.039s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16534,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:48.092626 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:48.117865 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.025s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5115,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.118337 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:48.129827 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.130466 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:48.170737 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushMRSOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.040s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1437,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1706,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:48.171489 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling LogGCOp(b56b1730feed4a989951f4a5c1c85ad3): free 120100588 bytes of WAL
I20260812 06:18:48.171725 16653 log_reader.cc:385] T b56b1730feed4a989951f4a5c1c85ad3: removed 12 log segments from log reader
I20260812 06:18:48.171769 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000028 (ops 136-140)
I20260812 06:18:48.171798 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000029 (ops 141-144)
I20260812 06:18:48.171860 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000030 (ops 145-149)
I20260812 06:18:48.171890 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000031 (ops 150-154)
I20260812 06:18:48.171936 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000032 (ops 155-158)
I20260812 06:18:48.171964 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000033 (ops 159-163)
I20260812 06:18:48.172000 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000034 (ops 164-168)
I20260812 06:18:48.172039 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000035 (ops 169-173)
I20260812 06:18:48.172078 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000036 (ops 174-178)
I20260812 06:18:48.172115 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000037 (ops 179-182)
I20260812 06:18:48.172153 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000038 (ops 183-187)
I20260812 06:18:48.172191 16653 log.cc:1079] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/b56b1730feed4a989951f4a5c1c85ad3/wal-000000039 (ops 188-192)
I20260812 06:18:48.200070 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: LogGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:48.200521 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3): 447 bytes on disk
I20260812 06:18:48.201004 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: UndoDeltaBlockGCOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.201586 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=3.181125
I20260812 06:18:48.220934 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5131,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.221451 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=2.188937
I20260812 06:18:48.235288 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: FlushDeltaMemStoresOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5420,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.235795 16720 maintenance_manager.cc:419] P 33153970800c497392a863517af5acd9: Scheduling MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3): perf score=1.000000
I20260812 06:18:48.318359 16538 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.059s	user 1.846s	sys 0.165s
I20260812 06:18:48.423799 16538 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.105s	user 0.003s	sys 0.000s
I20260812 06:18:48.424492 16538 tablet_server.cc:179] TabletServer@127.16.38.129:0 shutting down...
I20260812 06:18:48.446478 16653 maintenance_manager.cc:643] P 33153970800c497392a863517af5acd9: MajorDeltaCompactionOp(b56b1730feed4a989951f4a5c1c85ad3) complete. Timing: real 0.210s	user 0.126s	sys 0.083s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1330,"lbm_read_time_us":15440,"lbm_reads_lt_1ms":771,"lbm_write_time_us":37199,"lbm_writes_lt_1ms":743,"mutex_wait_us":133,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:18:48.447185 16538 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.447733 16538 tablet_replica.cc:333] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9: stopping tablet replica
I20260812 06:18:48.448024 16538 raft_consensus.cc:2243] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.448275 16538 raft_consensus.cc:2272] T b56b1730feed4a989951f4a5c1c85ad3 P 33153970800c497392a863517af5acd9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.479665 16538 tablet_server.cc:196] TabletServer@127.16.38.129:0 shutdown complete.
I20260812 06:18:48.505399 16538 master.cc:562] Master@127.16.38.190:45477 shutting down...
I20260812 06:18:48.509258 16538 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.509466 16538 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.509560 16538 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3205ecf1ff4d49d4aa3c0ea9cf63d976: stopping tablet replica
I20260812 06:18:48.521701 16538 master.cc:584] Master@127.16.38.190:45477 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5604 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:48.614789 16538 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.38.190:36325
I20260812 06:18:48.615268 16538 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:48.617379 16759 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:48.617478 16538 server_base.cc:1061] running on GCE node
W20260812 06:18:48.617545 16762 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:48.617576 16760 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:48.617970 16538 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:48.618013 16538 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:48.618029 16538 hybrid_clock.cc:648] HybridClock initialized: now 1786515528618029 us; error 0 us; skew 500 ppm
I20260812 06:18:48.618832 16538 webserver.cc:533] Webserver started at http://127.16.38.190:39097/ using document root <none> and password file <none>
I20260812 06:18:48.619016 16538 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:48.619083 16538 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:48.619192 16538 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:48.619602 16538 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/master-0-root/instance:
uuid: "a2f9391120444bd6a111c73544d6bb5c"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-1xrh"
I20260812 06:18:48.621107 16538 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:48.622069 16768 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:48.622320 16538 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:48.622395 16538 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/master-0-root
uuid: "a2f9391120444bd6a111c73544d6bb5c"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-1xrh"
I20260812 06:18:48.622458 16538 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-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:48.643785 16538 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:48.644096 16538 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:48.648165 16538 rpc_server.cc:307] RPC server started. Bound to: 127.16.38.190:36325
I20260812 06:18:48.658872 16829 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.38.190:36325 every 8 connection(s)
I20260812 06:18:48.659328 16830 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:48.661084 16830 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c: Bootstrap starting.
I20260812 06:18:48.662010 16830 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:48.663021 16830 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c: No bootstrap required, opened a new log
I20260812 06:18:48.663453 16830 raft_consensus.cc:359] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2f9391120444bd6a111c73544d6bb5c" member_type: VOTER }
I20260812 06:18:48.663561 16830 raft_consensus.cc:385] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:48.663614 16830 raft_consensus.cc:740] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a2f9391120444bd6a111c73544d6bb5c, State: Initialized, Role: FOLLOWER
I20260812 06:18:48.663784 16830 consensus_queue.cc:260] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [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: "a2f9391120444bd6a111c73544d6bb5c" member_type: VOTER }
I20260812 06:18:48.663882 16830 raft_consensus.cc:399] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:48.663929 16830 raft_consensus.cc:493] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:48.663986 16830 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:48.664654 16830 raft_consensus.cc:515] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2f9391120444bd6a111c73544d6bb5c" member_type: VOTER }
I20260812 06:18:48.664808 16830 leader_election.cc:304] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [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: a2f9391120444bd6a111c73544d6bb5c; no voters: 
I20260812 06:18:48.665000 16830 leader_election.cc:290] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:48.665107 16833 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:48.665361 16833 raft_consensus.cc:697] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 1 LEADER]: Becoming Leader. State: Replica: a2f9391120444bd6a111c73544d6bb5c, State: Running, Role: LEADER
I20260812 06:18:48.665469 16830 sys_catalog.cc:565] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:48.665506 16833 consensus_queue.cc:237] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [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: "a2f9391120444bd6a111c73544d6bb5c" member_type: VOTER }
I20260812 06:18:48.665930 16835 sys_catalog.cc:455] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [sys.catalog]: SysCatalogTable state changed. Reason: New leader a2f9391120444bd6a111c73544d6bb5c. Latest consensus state: current_term: 1 leader_uuid: "a2f9391120444bd6a111c73544d6bb5c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2f9391120444bd6a111c73544d6bb5c" member_type: VOTER } }
I20260812 06:18:48.665916 16834 sys_catalog.cc:455] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a2f9391120444bd6a111c73544d6bb5c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2f9391120444bd6a111c73544d6bb5c" member_type: VOTER } }
I20260812 06:18:48.666044 16834 sys_catalog.cc:458] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:48.666033 16835 sys_catalog.cc:458] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:48.666344 16841 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:48.667281 16841 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:48.667500 16538 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:48.669070 16841 catalog_manager.cc:1383] Generated new cluster ID: 48e4bd1de4da44cfb4c4aae57b911851
I20260812 06:18:48.669139 16841 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:48.679067 16841 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:48.679569 16841 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:48.691856 16841 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c: Generated new TSK 0
I20260812 06:18:48.692022 16841 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:48.699753 16538 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:48.701568 16855 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:48.701643 16857 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:48.701649 16859 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:48.701754 16538 server_base.cc:1061] running on GCE node
I20260812 06:18:48.701962 16538 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:48.702004 16538 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:48.702020 16538 hybrid_clock.cc:648] HybridClock initialized: now 1786515528702020 us; error 0 us; skew 500 ppm
I20260812 06:18:48.702840 16538 webserver.cc:533] Webserver started at http://127.16.38.129:45131/ using document root <none> and password file <none>
I20260812 06:18:48.702979 16538 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:48.703022 16538 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:48.703071 16538 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:48.703467 16538 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/instance:
uuid: "ab7f8693563f45078535380be2b88525"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-1xrh"
I20260812 06:18:48.704849 16538 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:48.705673 16864 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:48.705892 16538 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:48.705981 16538 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root
uuid: "ab7f8693563f45078535380be2b88525"
format_stamp: "Formatted at 2026-08-12 06:18:48 on dist-test-slave-1xrh"
I20260812 06:18:48.706063 16538 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-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:48.720657 16538 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:48.720974 16538 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:48.721253 16538 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:48.721684 16538 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:48.721743 16538 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:48.721805 16538 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:48.721856 16538 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:48.726227 16538 rpc_server.cc:307] RPC server started. Bound to: 127.16.38.129:45291
I20260812 06:18:48.727490 16937 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.38.129:45291 every 8 connection(s)
I20260812 06:18:48.736265 16938 heartbeater.cc:344] Connected to a master server at 127.16.38.190:36325
I20260812 06:18:48.736388 16938 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:48.736573 16938 heartbeater.cc:507] Master 127.16.38.190:36325 requested a full tablet report, sending...
I20260812 06:18:48.737193 16789 ts_manager.cc:194] Registered new tserver with Master: ab7f8693563f45078535380be2b88525 (127.16.38.129:45291)
I20260812 06:18:48.737895 16789 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56222
I20260812 06:18:48.738191 16538 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010948236s
I20260812 06:18:48.744895 16789 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56234:
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:48.753273 16895 tablet_service.cc:1511] Processing CreateTablet for tablet 5f4771220f9f4516a3e16dc5744850e2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ca538da35b584aa0b0fe7505acc750de]), partition=
I20260812 06:18:48.753556 16895 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5f4771220f9f4516a3e16dc5744850e2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:48.755587 16952 tablet_bootstrap.cc:492] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Bootstrap starting.
I20260812 06:18:48.756537 16952 tablet_bootstrap.cc:654] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:48.757586 16952 tablet_bootstrap.cc:492] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: No bootstrap required, opened a new log
I20260812 06:18:48.757683 16952 ts_tablet_manager.cc:1403] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:48.758131 16952 raft_consensus.cc:359] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab7f8693563f45078535380be2b88525" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 45291 } }
I20260812 06:18:48.758216 16952 raft_consensus.cc:385] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:48.758279 16952 raft_consensus.cc:740] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ab7f8693563f45078535380be2b88525, State: Initialized, Role: FOLLOWER
I20260812 06:18:48.758456 16952 consensus_queue.cc:260] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [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: "ab7f8693563f45078535380be2b88525" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 45291 } }
I20260812 06:18:48.758555 16952 raft_consensus.cc:399] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:48.758602 16952 raft_consensus.cc:493] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:48.758663 16952 raft_consensus.cc:3060] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:48.759650 16952 raft_consensus.cc:515] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab7f8693563f45078535380be2b88525" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 45291 } }
I20260812 06:18:48.759778 16952 leader_election.cc:304] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [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: ab7f8693563f45078535380be2b88525; no voters: 
I20260812 06:18:48.759934 16952 leader_election.cc:290] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:48.760082 16954 raft_consensus.cc:2804] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:48.760241 16952 ts_tablet_manager.cc:1434] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:48.760321 16954 raft_consensus.cc:697] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 1 LEADER]: Becoming Leader. State: Replica: ab7f8693563f45078535380be2b88525, State: Running, Role: LEADER
I20260812 06:18:48.760249 16938 heartbeater.cc:499] Master 127.16.38.190:36325 was elected leader, sending a full tablet report...
I20260812 06:18:48.760473 16954 consensus_queue.cc:237] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [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: "ab7f8693563f45078535380be2b88525" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 45291 } }
I20260812 06:18:48.761781 16789 catalog_manager.cc:5719] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 reported cstate change: term changed from 0 to 1, leader changed from <none> to ab7f8693563f45078535380be2b88525 (127.16.38.129). New cstate: current_term: 1 leader_uuid: "ab7f8693563f45078535380be2b88525" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab7f8693563f45078535380be2b88525" member_type: VOTER last_known_addr { host: "127.16.38.129" port: 45291 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:48.822120 16538 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.004s
I20260812 06:18:48.978022 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2): perf score=19.054940
I20260812 06:18:49.135560 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.157s	user 0.109s	sys 0.048s Metrics: {"bytes_written":13045921,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1727,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40409,"lbm_writes_lt_1ms":775,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1590}
I20260812 06:18:49.136394 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling LogGCOp(5f4771220f9f4516a3e16dc5744850e2): free 20290830 bytes of WAL
I20260812 06:18:49.136689 16869 log_reader.cc:385] T 5f4771220f9f4516a3e16dc5744850e2: removed 2 log segments from log reader
I20260812 06:18:49.136780 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000001 (ops 1-6)
I20260812 06:18:49.136835 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000002 (ops 7-10)
I20260812 06:18:49.143030 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: LogGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:49.143460 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2): 16411393 bytes on disk
I20260812 06:18:49.143872 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.144305 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:49.170102 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.026s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":6274,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:49.170524 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:49.184011 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5371,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.184492 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:49.351696 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.167s	user 0.127s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774785,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":264,"lbm_read_time_us":13518,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29500,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":301,"threads_started":5,"update_count":2500}
I20260812 06:18:49.352257 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:49.404966 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.052s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23761,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.405423 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:49.420727 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6123,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.421299 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:49.587143 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.166s	user 0.129s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1334,"lbm_read_time_us":10947,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30737,"lbm_writes_lt_1ms":543,"mutex_wait_us":389,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:49.587720 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:49.648207 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.060s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23718,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.648638 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:49.659103 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.659832 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:49.833688 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.174s	user 0.134s	sys 0.040s 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":1068,"lbm_read_time_us":14397,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28406,"lbm_writes_lt_1ms":543,"mutex_wait_us":210,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:18:49.834242 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:49.894649 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.060s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.895308 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:49.906169 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.906675 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:50.091532 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.185s	user 0.117s	sys 0.068s 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":264,"lbm_read_time_us":13561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31052,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":2500}
I20260812 06:18:50.092195 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:50.158058 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.066s	user 0.022s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26590,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.158533 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:50.169659 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.170092 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:50.375298 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.205s	user 0.140s	sys 0.056s 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":666,"lbm_read_time_us":14422,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33809,"lbm_writes_lt_1ms":543,"mutex_wait_us":87,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:18:50.376073 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:50.432621 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.056s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27698,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.433125 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:50.453955 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.021s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.454481 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:50.489786 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.035s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1463,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2186,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:50.490535 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling LogGCOp(5f4771220f9f4516a3e16dc5744850e2): free 121006379 bytes of WAL
I20260812 06:18:50.490913 16869 log_reader.cc:385] T 5f4771220f9f4516a3e16dc5744850e2: removed 12 log segments from log reader
I20260812 06:18:50.491010 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000003 (ops 11-15)
I20260812 06:18:50.491081 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000004 (ops 16-20)
I20260812 06:18:50.491173 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000005 (ops 21-24)
I20260812 06:18:50.491235 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000006 (ops 25-29)
I20260812 06:18:50.491340 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000007 (ops 30-34)
I20260812 06:18:50.491381 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000008 (ops 35-39)
I20260812 06:18:50.491415 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000009 (ops 40-44)
I20260812 06:18:50.491438 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000010 (ops 45-49)
I20260812 06:18:50.491467 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000011 (ops 50-54)
I20260812 06:18:50.491499 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000012 (ops 55-59)
I20260812 06:18:50.491531 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000013 (ops 60-64)
I20260812 06:18:50.491596 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000014 (ops 65-69)
I20260812 06:18:50.521356 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: LogGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:50.522727 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=5.165500
I20260812 06:18:50.542654 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.020s	user 0.011s	sys 0.005s Metrics: {"bytes_written":7425618,"delete_count":0,"lbm_write_time_us":7871,"lbm_writes_lt_1ms":184,"reinsert_count":0,"update_count":905}
I20260812 06:18:50.543540 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:50.789537 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.246s	user 0.154s	sys 0.091s Metrics: {"cfile_cache_miss":714,"cfile_cache_miss_bytes":32200174,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":741,"lbm_read_time_us":17906,"lbm_reads_lt_1ms":750,"lbm_write_time_us":39865,"lbm_writes_lt_1ms":724,"mutex_wait_us":425,"peak_mem_usage":85108611,"reinsert_count":0,"spinlock_wait_cycles":38272,"thread_start_us":130,"threads_started":1,"update_count":3405}
I20260812 06:18:50.790373 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2): 483 bytes on disk
I20260812 06:18:50.791610 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.792217 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=19.056125
I20260812 06:18:50.851642 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.059s	user 0.028s	sys 0.027s Metrics: {"bytes_written":21291781,"delete_count":0,"lbm_write_time_us":25896,"lbm_writes_lt_1ms":522,"reinsert_count":0,"update_count":2595}
I20260812 06:18:50.852155 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling LogGCOp(5f4771220f9f4516a3e16dc5744850e2): free 12017983 bytes of WAL
I20260812 06:18:50.852386 16869 log_reader.cc:385] T 5f4771220f9f4516a3e16dc5744850e2: removed 1 log segments from log reader
I20260812 06:18:50.852448 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000015 (ops 70-74)
I20260812 06:18:50.854976 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: LogGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:50.855309 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:50.866894 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.867463 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:51.081827 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.214s	user 0.143s	sys 0.070s Metrics: {"cfile_cache_miss":651,"cfile_cache_miss_bytes":29656568,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":654,"lbm_read_time_us":15759,"lbm_reads_lt_1ms":691,"lbm_write_time_us":35658,"lbm_writes_lt_1ms":662,"mutex_wait_us":30,"peak_mem_usage":77362521,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3095}
I20260812 06:18:51.082322 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=18.063937
I20260812 06:18:51.137698 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.055s	user 0.038s	sys 0.012s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24263,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:51.138180 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:51.303105 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.165s	user 0.120s	sys 0.044s 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":970,"lbm_read_time_us":13735,"lbm_reads_lt_1ms":563,"lbm_write_time_us":26832,"lbm_writes_lt_1ms":543,"mutex_wait_us":386,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:18:51.303889 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:51.368589 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.064s	user 0.035s	sys 0.026s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22962,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.369146 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:51.380241 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.380714 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:51.574297 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.193s	user 0.150s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":316,"lbm_read_time_us":15505,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31754,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:51.575073 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:51.627065 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.052s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22490,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.627619 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:51.655927 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.028s	user 0.013s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.656533 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:51.835711 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.179s	user 0.111s	sys 0.068s 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":229,"lbm_read_time_us":14276,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27896,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:51.836520 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:51.892653 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.056s	user 0.047s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.893518 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:51.932518 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.039s	user 0.012s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.933080 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:51.943882 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.944365 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:51.977140 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.033s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1581,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1561,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:51.977866 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2): 447 bytes on disk
I20260812 06:18:51.978353 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.978919 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:52.194443 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.215s	user 0.133s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":124,"lbm_read_time_us":16125,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34879,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:18:52.195365 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling LogGCOp(5f4771220f9f4516a3e16dc5744850e2): free 108535456 bytes of WAL
I20260812 06:18:52.195601 16869 log_reader.cc:385] T 5f4771220f9f4516a3e16dc5744850e2: removed 11 log segments from log reader
I20260812 06:18:52.195664 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000016 (ops 75-79)
I20260812 06:18:52.195746 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000017 (ops 80-84)
I20260812 06:18:52.195811 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000018 (ops 85-88)
I20260812 06:18:52.195886 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000019 (ops 89-93)
I20260812 06:18:52.195943 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000020 (ops 94-98)
I20260812 06:18:52.196017 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000021 (ops 99-103)
I20260812 06:18:52.196058 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000022 (ops 104-108)
I20260812 06:18:52.196126 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000023 (ops 109-112)
I20260812 06:18:52.196166 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000024 (ops 113-117)
I20260812 06:18:52.196205 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000025 (ops 118-122)
I20260812 06:18:52.196249 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000026 (ops 123-127)
I20260812 06:18:52.222541 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: LogGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:52.223097 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=18.063937
I20260812 06:18:52.289336 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.066s	user 0.026s	sys 0.032s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27660,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.289860 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=3.181125
I20260812 06:18:52.301769 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5031,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.302199 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:52.311908 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4017,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.312281 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:52.529917 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.217s	user 0.155s	sys 0.062s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979624,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":278,"lbm_read_time_us":19119,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39949,"lbm_writes_lt_1ms":743,"mutex_wait_us":74,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3500}
I20260812 06:18:52.530843 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=18.063937
I20260812 06:18:52.594488 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.063s	user 0.048s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28395,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.594949 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=3.181125
I20260812 06:18:52.610358 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.610772 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:52.620326 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3852,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.620723 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:52.820143 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.199s	user 0.167s	sys 0.031s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979623,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1211,"lbm_read_time_us":16598,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41386,"lbm_writes_lt_1ms":743,"mutex_wait_us":470,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":3500}
I20260812 06:18:52.820943 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:52.861872 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.041s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:52.862416 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:52.881119 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.881631 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:53.043304 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.161s	user 0.092s	sys 0.069s 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":507,"lbm_read_time_us":10302,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31015,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:53.044097 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:53.097260 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.053s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22753,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.097842 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:53.249456 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.151s	user 0.114s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":145,"lbm_read_time_us":11416,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23474,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:18:53.250514 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=14.095187
I20260812 06:18:53.308472 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.058s	user 0.041s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.309194 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:53.339025 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.030s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.339625 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:53.355728 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.016s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.356335 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:53.394604 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushMRSOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.038s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1459,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2324,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:53.395339 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling LogGCOp(5f4771220f9f4516a3e16dc5744850e2): free 120553581 bytes of WAL
I20260812 06:18:53.395560 16869 log_reader.cc:385] T 5f4771220f9f4516a3e16dc5744850e2: removed 12 log segments from log reader
I20260812 06:18:53.395601 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000027 (ops 128-132)
I20260812 06:18:53.395629 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000028 (ops 133-137)
I20260812 06:18:53.395691 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000029 (ops 138-142)
I20260812 06:18:53.395735 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000030 (ops 143-147)
I20260812 06:18:53.395774 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000031 (ops 148-152)
I20260812 06:18:53.395818 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000032 (ops 153-157)
I20260812 06:18:53.395860 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000033 (ops 158-162)
I20260812 06:18:53.395900 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000034 (ops 163-166)
I20260812 06:18:53.395942 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000035 (ops 167-171)
I20260812 06:18:53.395984 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000036 (ops 172-176)
I20260812 06:18:53.396024 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000037 (ops 177-180)
I20260812 06:18:53.396070 16869 log.cc:1079] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: Deleting log segment in path: /tmp/dist-test-taskwMBoPr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515522999259-16538-0/minicluster-data/ts-0-root/wals/5f4771220f9f4516a3e16dc5744850e2/wal-000000038 (ops 181-185)
I20260812 06:18:53.425333 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: LogGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:53.426115 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2): 461 bytes on disk
I20260812 06:18:53.426584 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: UndoDeltaBlockGCOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.427309 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=3.181125
I20260812 06:18:53.440688 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4601,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:53.441126 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=2.188937
I20260812 06:18:53.451399 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:53.451799 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2): perf score=1.000000
I20260812 06:18:53.702379 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: MajorDeltaCompactionOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.250s	user 0.162s	sys 0.087s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":264,"lbm_read_time_us":21139,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45140,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":81,"threads_started":1,"update_count":4000}
I20260812 06:18:53.704407 16939 maintenance_manager.cc:419] P ab7f8693563f45078535380be2b88525: Scheduling FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2): perf score=18.063937
I20260812 06:18:53.726302 16538 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.904s	user 1.759s	sys 0.195s
I20260812 06:18:53.761663 16538 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.035s	user 0.001s	sys 0.000s
I20260812 06:18:53.762187 16538 tablet_server.cc:179] TabletServer@127.16.38.129:0 shutting down...
I20260812 06:18:53.778482 16869 maintenance_manager.cc:643] P ab7f8693563f45078535380be2b88525: FlushDeltaMemStoresOp(5f4771220f9f4516a3e16dc5744850e2) complete. Timing: real 0.074s	user 0.032s	sys 0.038s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":35148,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:53.779003 16538 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:53.779213 16538 tablet_replica.cc:333] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525: stopping tablet replica
I20260812 06:18:53.779377 16538 raft_consensus.cc:2243] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:53.779551 16538 raft_consensus.cc:2272] T 5f4771220f9f4516a3e16dc5744850e2 P ab7f8693563f45078535380be2b88525 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:53.783972 16538 tablet_server.cc:196] TabletServer@127.16.38.129:0 shutdown complete.
I20260812 06:18:53.786748 16538 master.cc:562] Master@127.16.38.190:36325 shutting down...
I20260812 06:18:53.789904 16538 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:53.790076 16538 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:53.790155 16538 tablet_replica.cc:333] T 00000000000000000000000000000000 P a2f9391120444bd6a111c73544d6bb5c: stopping tablet replica
I20260812 06:18:53.802352 16538 master.cc:584] Master@127.16.38.190:36325 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5282 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10888 ms total)

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