[==========] 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:19:55.480512 25766 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.41.190:42645
I20260812 06:19:55.481557 25766 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:19:55.482180 25766 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:55.490525 25780 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:19:55.490909 25777 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:19:55.490701 25776 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:19:55.490995 25766 server_base.cc:1061] running on GCE node
I20260812 06:19:55.492491 25766 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:55.492648 25766 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:19:55.492705 25766 hybrid_clock.cc:648] HybridClock initialized: now 1786515595492702 us; error 0 us; skew 500 ppm
I20260812 06:19:55.494649 25766 webserver.cc:533] Webserver started at http://127.25.41.190:40811/ using document root <none> and password file <none>
I20260812 06:19:55.495246 25766 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:55.495342 25766 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:55.495595 25766 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:55.497382 25766 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/master-0-root/instance:
uuid: "191ee1738bd8428f84780221663ee78f"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-ffrd"
I20260812 06:19:55.500922 25766 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:55.503090 25788 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:19:55.504087 25766 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:55.504236 25766 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/master-0-root
uuid: "191ee1738bd8428f84780221663ee78f"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-ffrd"
I20260812 06:19:55.504346 25766 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-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:19:55.514577 25766 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:55.515169 25766 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:19:55.515352 25766 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:55.523394 25766 rpc_server.cc:307] RPC server started. Bound to: 127.25.41.190:42645
I20260812 06:19:55.523459 25873 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.41.190:42645 every 8 connection(s)
I20260812 06:19:55.525774 25874 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:19:55.531370 25874 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f: Bootstrap starting.
I20260812 06:19:55.533828 25874 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:55.534739 25874 log.cc:826] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:55.536461 25874 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f: No bootstrap required, opened a new log
I20260812 06:19:55.539212 25874 raft_consensus.cc:359] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "191ee1738bd8428f84780221663ee78f" member_type: VOTER }
I20260812 06:19:55.539372 25874 raft_consensus.cc:385] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:55.539445 25874 raft_consensus.cc:740] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 191ee1738bd8428f84780221663ee78f, State: Initialized, Role: FOLLOWER
I20260812 06:19:55.540066 25874 consensus_queue.cc:260] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [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: "191ee1738bd8428f84780221663ee78f" member_type: VOTER }
I20260812 06:19:55.540284 25874 raft_consensus.cc:399] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:55.540360 25874 raft_consensus.cc:493] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:55.540520 25874 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:55.541383 25874 raft_consensus.cc:515] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "191ee1738bd8428f84780221663ee78f" member_type: VOTER }
I20260812 06:19:55.541821 25874 leader_election.cc:304] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [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: 191ee1738bd8428f84780221663ee78f; no voters: 
I20260812 06:19:55.542135 25874 leader_election.cc:290] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:55.542282 25881 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:55.542539 25881 raft_consensus.cc:697] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 1 LEADER]: Becoming Leader. State: Replica: 191ee1738bd8428f84780221663ee78f, State: Running, Role: LEADER
I20260812 06:19:55.542984 25881 consensus_queue.cc:237] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [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: "191ee1738bd8428f84780221663ee78f" member_type: VOTER }
I20260812 06:19:55.543097 25874 sys_catalog.cc:565] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:55.544804 25883 sys_catalog.cc:455] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "191ee1738bd8428f84780221663ee78f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "191ee1738bd8428f84780221663ee78f" member_type: VOTER } }
I20260812 06:19:55.544811 25885 sys_catalog.cc:455] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 191ee1738bd8428f84780221663ee78f. Latest consensus state: current_term: 1 leader_uuid: "191ee1738bd8428f84780221663ee78f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "191ee1738bd8428f84780221663ee78f" member_type: VOTER } }
I20260812 06:19:55.544963 25883 sys_catalog.cc:458] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:55.544989 25885 sys_catalog.cc:458] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:55.545356 25900 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:55.545614 25766 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:55.547760 25900 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:55.552726 25900 catalog_manager.cc:1383] Generated new cluster ID: 0ee609c8c5a64c95a4e95ca5ca3ae4e4
I20260812 06:19:55.552809 25900 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:55.566751 25900 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:55.567623 25900 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:55.587458 25900 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f: Generated new TSK 0
I20260812 06:19:55.588125 25900 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:55.610488 25766 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:55.613685 25915 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:19:55.613749 25916 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:19:55.613760 25920 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:19:55.614125 25766 server_base.cc:1061] running on GCE node
I20260812 06:19:55.614369 25766 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:55.614428 25766 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:19:55.614463 25766 hybrid_clock.cc:648] HybridClock initialized: now 1786515595614462 us; error 0 us; skew 500 ppm
I20260812 06:19:55.615351 25766 webserver.cc:533] Webserver started at http://127.25.41.129:46513/ using document root <none> and password file <none>
I20260812 06:19:55.615554 25766 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:55.615628 25766 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:55.615708 25766 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:55.616123 25766 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/instance:
uuid: "642cf49b78774dcfac1b6acf971595c0"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-ffrd"
I20260812 06:19:55.617743 25766 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:55.618742 25927 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:19:55.619025 25766 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:55.619098 25766 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root
uuid: "642cf49b78774dcfac1b6acf971595c0"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-ffrd"
I20260812 06:19:55.619189 25766 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-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:19:55.636236 25766 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:55.637076 25766 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:55.637648 25766 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:55.638568 25766 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:55.638621 25766 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:55.638685 25766 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:55.638732 25766 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:55.646102 25766 rpc_server.cc:307] RPC server started. Bound to: 127.25.41.129:43149
I20260812 06:19:55.646389 26030 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.41.129:43149 every 8 connection(s)
I20260812 06:19:55.661592 26031 heartbeater.cc:344] Connected to a master server at 127.25.41.190:42645
I20260812 06:19:55.661875 26031 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:55.662400 26031 heartbeater.cc:507] Master 127.25.41.190:42645 requested a full tablet report, sending...
I20260812 06:19:55.664119 25815 ts_manager.cc:194] Registered new tserver with Master: 642cf49b78774dcfac1b6acf971595c0 (127.25.41.129:43149)
I20260812 06:19:55.664232 25766 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017393189s
I20260812 06:19:55.665769 25815 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49294
I20260812 06:19:55.676482 25815 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49302:
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:19:55.692410 25970 tablet_service.cc:1511] Processing CreateTablet for tablet 8cc865413cea4171b09c368d5c026a51 (DEFAULT_TABLE table=heavy-update-compaction-test [id=06b6c3eed4534001ac5f356a381a158b]), partition=
I20260812 06:19:55.693038 25970 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8cc865413cea4171b09c368d5c026a51. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:55.695453 26049 tablet_bootstrap.cc:492] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Bootstrap starting.
I20260812 06:19:55.697011 26049 tablet_bootstrap.cc:654] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:55.698278 26049 tablet_bootstrap.cc:492] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: No bootstrap required, opened a new log
I20260812 06:19:55.698407 26049 ts_tablet_manager.cc:1403] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:55.698915 26049 raft_consensus.cc:359] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "642cf49b78774dcfac1b6acf971595c0" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 43149 } }
I20260812 06:19:55.699054 26049 raft_consensus.cc:385] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:55.699100 26049 raft_consensus.cc:740] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 642cf49b78774dcfac1b6acf971595c0, State: Initialized, Role: FOLLOWER
I20260812 06:19:55.699244 26049 consensus_queue.cc:260] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [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: "642cf49b78774dcfac1b6acf971595c0" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 43149 } }
I20260812 06:19:55.699362 26049 raft_consensus.cc:399] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:55.699414 26049 raft_consensus.cc:493] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:55.699468 26049 raft_consensus.cc:3060] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:55.700227 26049 raft_consensus.cc:515] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "642cf49b78774dcfac1b6acf971595c0" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 43149 } }
I20260812 06:19:55.700392 26049 leader_election.cc:304] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [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: 642cf49b78774dcfac1b6acf971595c0; no voters: 
I20260812 06:19:55.700649 26049 leader_election.cc:290] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:55.701038 26049 ts_tablet_manager.cc:1434] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:55.701056 26052 raft_consensus.cc:2804] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:55.701244 26052 raft_consensus.cc:697] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 1 LEADER]: Becoming Leader. State: Replica: 642cf49b78774dcfac1b6acf971595c0, State: Running, Role: LEADER
I20260812 06:19:55.701390 26052 consensus_queue.cc:237] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [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: "642cf49b78774dcfac1b6acf971595c0" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 43149 } }
I20260812 06:19:55.701619 26031 heartbeater.cc:499] Master 127.25.41.190:42645 was elected leader, sending a full tablet report...
I20260812 06:19:55.704186 25815 catalog_manager.cc:5719] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 reported cstate change: term changed from 0 to 1, leader changed from <none> to 642cf49b78774dcfac1b6acf971595c0 (127.25.41.129). New cstate: current_term: 1 leader_uuid: "642cf49b78774dcfac1b6acf971595c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "642cf49b78774dcfac1b6acf971595c0" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 43149 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:55.768646 25766 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.010s
I20260812 06:19:55.898290 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushMRSOp(8cc865413cea4171b09c368d5c026a51): perf score=15.086190
I20260812 06:19:56.047703 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushMRSOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.149s	user 0.123s	sys 0.024s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":282,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":753,"drs_written":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38463,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":160,"threads_started":1,"update_count":1450}
I20260812 06:19:56.048796 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51): 12719216 bytes on disk
I20260812 06:19:56.049386 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51) 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:19:56.049765 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:56.062121 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.012s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1271931,"delete_count":0,"lbm_write_time_us":1333,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:19:56.062670 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling LogGCOp(8cc865413cea4171b09c368d5c026a51): free 20743880 bytes of WAL
I20260812 06:19:56.063062 25934 log_reader.cc:385] T 8cc865413cea4171b09c368d5c026a51: removed 2 log segments from log reader
I20260812 06:19:56.063184 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000001 (ops 1-6)
I20260812 06:19:56.063292 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000002 (ops 7-11)
I20260812 06:19:56.069682 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: LogGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:19:56.070046 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=1.196750
I20260812 06:19:56.081912 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:56.082419 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:56.227865 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.145s	user 0.122s	sys 0.017s Metrics: {"cfile_cache_miss":423,"cfile_cache_miss_bytes":20262061,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":900,"lbm_read_time_us":11618,"lbm_reads_lt_1ms":459,"lbm_write_time_us":25375,"lbm_writes_lt_1ms":433,"mutex_wait_us":4,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":314,"threads_started":5,"update_count":1950}
I20260812 06:19:56.228487 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:56.274542 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.046s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16036,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.275061 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:56.286072 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.286919 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:56.415966 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.129s	user 0.090s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":10352,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25768,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:56.416563 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:56.469309 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.053s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.469823 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:56.481253 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.481823 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:56.625571 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.144s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":159,"lbm_read_time_us":12269,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24546,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:19:56.626163 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:56.670841 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.044s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19934,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.671422 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:56.685331 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.685859 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:56.809194 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.123s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":9906,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23102,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:19:56.809782 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:56.855882 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.046s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18123,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.856384 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:56.868367 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.012s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.868973 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:57.013849 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.145s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":8881,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25537,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39424,"update_count":2000}
I20260812 06:19:57.014528 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:57.061594 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.047s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17807,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.062094 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:57.074373 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.074923 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:57.206965 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.132s	user 0.095s	sys 0.037s 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":549,"lbm_read_time_us":10213,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24602,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:19:57.207590 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:57.258569 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.051s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.259140 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:57.269928 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.270321 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:57.418612 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.148s	user 0.100s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":12460,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23235,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:19:57.419251 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:19:57.464830 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.045s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16927,"lbm_writes_lt_1ms":303,"mutex_wait_us":17,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.465296 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:57.476125 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.476802 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushMRSOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:57.514861 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushMRSOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.038s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1125,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1721,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:57.515856 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling LogGCOp(8cc865413cea4171b09c368d5c026a51): free 124710303 bytes of WAL
I20260812 06:19:57.516106 25934 log_reader.cc:385] T 8cc865413cea4171b09c368d5c026a51: removed 12 log segments from log reader
I20260812 06:19:57.516176 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000003 (ops 12-16)
I20260812 06:19:57.516233 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000004 (ops 17-21)
I20260812 06:19:57.516285 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000005 (ops 22-26)
I20260812 06:19:57.516328 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000006 (ops 27-31)
I20260812 06:19:57.516355 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000007 (ops 32-36)
I20260812 06:19:57.516397 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000008 (ops 37-41)
I20260812 06:19:57.516428 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000009 (ops 42-46)
I20260812 06:19:57.516469 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000010 (ops 47-51)
I20260812 06:19:57.516496 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000011 (ops 52-56)
I20260812 06:19:57.516535 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000012 (ops 57-61)
I20260812 06:19:57.516574 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000013 (ops 62-66)
I20260812 06:19:57.516613 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000014 (ops 67-71)
I20260812 06:19:57.544538 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: LogGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:57.544924 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=5.165500
I20260812 06:19:57.570564 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.025s	user 0.008s	sys 0.016s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":7036,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:19:57.571133 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:57.578377 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.007s	user 0.001s	sys 0.005s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":2103,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:19:57.578840 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:57.780812 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.202s	user 0.148s	sys 0.054s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":244,"lbm_read_time_us":15069,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35481,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:57.781605 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51): 483 bytes on disk
I20260812 06:19:57.782157 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.784893 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:57.844498 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.059s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21522,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.845172 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:57.861821 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.016s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.862447 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:58.060832 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.198s	user 0.143s	sys 0.039s 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":196,"lbm_read_time_us":15174,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33118,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:58.061481 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:58.112048 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.050s	user 0.039s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22501,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.112493 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:58.124089 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.124589 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:58.323832 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.199s	user 0.131s	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":519,"lbm_read_time_us":12370,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31370,"lbm_writes_lt_1ms":543,"mutex_wait_us":107,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:19:58.324342 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:58.383287 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.059s	user 0.019s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25436,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.383769 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:58.395296 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.396091 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:58.565737 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.169s	user 0.133s	sys 0.031s 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":287,"lbm_read_time_us":11600,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34097,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:58.566326 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=11.118625
I20260812 06:19:58.606627 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.040s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17493,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:58.607280 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:58.632695 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5651,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.633168 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:58.643496 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.643900 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:58.810686 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.167s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":720,"lbm_read_time_us":12465,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31349,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:19:58.811378 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:58.861243 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22296,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.861828 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:58.877483 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.877981 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:59.025686 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.147s	user 0.112s	sys 0.032s 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":234,"lbm_read_time_us":10401,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29460,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:19:59.026413 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:59.076462 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.050s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17999,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.077128 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:59.092748 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.093734 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushMRSOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:59.127310 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushMRSOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1240,"drs_written":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1815,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":18304}
I20260812 06:19:59.128078 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling LogGCOp(8cc865413cea4171b09c368d5c026a51): free 128867475 bytes of WAL
I20260812 06:19:59.128373 25934 log_reader.cc:385] T 8cc865413cea4171b09c368d5c026a51: removed 13 log segments from log reader
I20260812 06:19:59.128432 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000015 (ops 72-76)
I20260812 06:19:59.128487 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000016 (ops 77-80)
I20260812 06:19:59.128539 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000017 (ops 81-85)
I20260812 06:19:59.128559 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000018 (ops 86-90)
I20260812 06:19:59.128613 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000019 (ops 91-95)
I20260812 06:19:59.128674 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000020 (ops 96-100)
I20260812 06:19:59.128711 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000021 (ops 101-105)
I20260812 06:19:59.128753 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000022 (ops 106-110)
I20260812 06:19:59.128786 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000023 (ops 111-114)
I20260812 06:19:59.128834 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000024 (ops 115-119)
I20260812 06:19:59.128876 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000025 (ops 120-124)
I20260812 06:19:59.128921 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000026 (ops 125-128)
I20260812 06:19:59.128985 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000027 (ops 129-133)
I20260812 06:19:59.158286 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: LogGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:19:59.158721 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51): 492 bytes on disk
I20260812 06:19:59.159226 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:59.160197 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=6.157687
I20260812 06:19:59.183061 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.023s	user 0.008s	sys 0.013s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":9610,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:59.183561 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:59.391019 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.207s	user 0.149s	sys 0.053s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979632,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2545,"lbm_read_time_us":14088,"lbm_reads_lt_1ms":769,"lbm_write_time_us":40748,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":1555,"threads_started":1,"update_count":3500}
I20260812 06:19:59.391840 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:59.450490 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.058s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20057,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.451020 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:59.472347 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.021s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6413,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.472913 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:59.645902 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.173s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":911,"lbm_read_time_us":13477,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27594,"lbm_writes_lt_1ms":543,"mutex_wait_us":4,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:59.646627 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:19:59.705349 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.059s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25731,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.706039 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:59.747378 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.041s	user 0.008s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.747979 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:19:59.759104 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.759608 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:19:59.971174 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.211s	user 0.151s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":891,"lbm_read_time_us":16129,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39535,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":3000}
I20260812 06:19:59.971642 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:20:00.041132 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.069s	user 0.038s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25454,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.041813 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:20:00.059381 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.059991 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:20:00.248672 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.188s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":13489,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31303,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:20:00.249298 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:20:00.313781 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.064s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19326,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.314246 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:20:00.324903 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.325443 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:20:00.509516 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.184s	user 0.132s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":14203,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30916,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:20:00.510174 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=14.095187
I20260812 06:20:00.566074 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.056s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.566579 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:20:00.578428 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.012s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.578999 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushMRSOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:20:00.615907 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushMRSOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.037s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1336,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1972,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:00.616748 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling LogGCOp(8cc865413cea4171b09c368d5c026a51): free 120553636 bytes of WAL
I20260812 06:20:00.617067 25934 log_reader.cc:385] T 8cc865413cea4171b09c368d5c026a51: removed 12 log segments from log reader
I20260812 06:20:00.617129 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000028 (ops 134-138)
I20260812 06:20:00.617168 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000029 (ops 139-142)
I20260812 06:20:00.617198 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000030 (ops 143-147)
I20260812 06:20:00.617229 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000031 (ops 148-152)
I20260812 06:20:00.617264 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000032 (ops 153-156)
I20260812 06:20:00.617290 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000033 (ops 157-161)
I20260812 06:20:00.617312 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000034 (ops 162-166)
I20260812 06:20:00.617340 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000035 (ops 167-171)
I20260812 06:20:00.617370 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000036 (ops 172-176)
I20260812 06:20:00.617403 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000037 (ops 177-181)
I20260812 06:20:00.617448 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000038 (ops 182-186)
I20260812 06:20:00.617480 25934 log.cc:1079] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/8cc865413cea4171b09c368d5c026a51/wal-000000039 (ops 187-191)
I20260812 06:20:00.651700 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: LogGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.035s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:20:00.652150 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51): 448 bytes on disk
I20260812 06:20:00.652622 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: UndoDeltaBlockGCOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.653280 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=3.181125
I20260812 06:20:00.667557 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5079,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:00.668102 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=2.188937
I20260812 06:20:00.682940 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5868,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.683593 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51): perf score=1.000000
I20260812 06:20:00.819835 25766 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.051s	user 1.813s	sys 0.156s
I20260812 06:20:00.904624 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: MajorDeltaCompactionOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.221s	user 0.129s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1119,"lbm_read_time_us":17650,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38185,"lbm_writes_lt_1ms":743,"mutex_wait_us":377,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9856,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:20:00.905393 26033 maintenance_manager.cc:419] P 642cf49b78774dcfac1b6acf971595c0: Scheduling FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51): perf score=10.126437
I20260812 06:20:00.915707 25766 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.002s	sys 0.000s
I20260812 06:20:00.916782 25766 tablet_server.cc:179] TabletServer@127.25.41.129:0 shutting down...
I20260812 06:20:00.939764 25934 maintenance_manager.cc:643] P 642cf49b78774dcfac1b6acf971595c0: FlushDeltaMemStoresOp(8cc865413cea4171b09c368d5c026a51) complete. Timing: real 0.034s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15347,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.940356 25766 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:00.940793 25766 tablet_replica.cc:333] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0: stopping tablet replica
I20260812 06:20:00.941087 25766 raft_consensus.cc:2243] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:00.941320 25766 raft_consensus.cc:2272] T 8cc865413cea4171b09c368d5c026a51 P 642cf49b78774dcfac1b6acf971595c0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:00.957237 25766 tablet_server.cc:196] TabletServer@127.25.41.129:0 shutdown complete.
I20260812 06:20:00.963860 25766 master.cc:562] Master@127.25.41.190:42645 shutting down...
I20260812 06:20:00.967813 25766 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:00.968015 25766 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:00.968104 25766 tablet_replica.cc:333] T 00000000000000000000000000000000 P 191ee1738bd8428f84780221663ee78f: stopping tablet replica
I20260812 06:20:00.980511 25766 master.cc:584] Master@127.25.41.190:42645 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5594 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:01.074879 25766 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.41.190:39993
I20260812 06:20:01.075294 25766 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:01.077394 26082 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:20:01.077418 26083 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:20:01.077570 26087 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:20:01.077683 25766 server_base.cc:1061] running on GCE node
I20260812 06:20:01.077795 25766 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:01.077827 25766 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:20:01.077842 25766 hybrid_clock.cc:648] HybridClock initialized: now 1786515601077843 us; error 0 us; skew 500 ppm
I20260812 06:20:01.078645 25766 webserver.cc:533] Webserver started at http://127.25.41.190:39167/ using document root <none> and password file <none>
I20260812 06:20:01.078773 25766 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:01.078814 25766 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:01.078866 25766 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:01.079208 25766 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/master-0-root/instance:
uuid: "a4a397ead85d45eaa0c32b54a90163f7"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-ffrd"
I20260812 06:20:01.080627 25766 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:01.081720 26095 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:20:01.082044 25766 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:01.082115 25766 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/master-0-root
uuid: "a4a397ead85d45eaa0c32b54a90163f7"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-ffrd"
I20260812 06:20:01.082226 25766 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-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:20:01.101672 25766 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:01.102079 25766 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:01.106236 25766 rpc_server.cc:307] RPC server started. Bound to: 127.25.41.190:39993
I20260812 06:20:01.110100 26177 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.41.190:39993 every 8 connection(s)
I20260812 06:20:01.112366 26179 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:20:01.124760 26179 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7: Bootstrap starting.
I20260812 06:20:01.125645 26179 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:01.126663 26179 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7: No bootstrap required, opened a new log
I20260812 06:20:01.127031 26179 raft_consensus.cc:359] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4a397ead85d45eaa0c32b54a90163f7" member_type: VOTER }
I20260812 06:20:01.127120 26179 raft_consensus.cc:385] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:01.127141 26179 raft_consensus.cc:740] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4a397ead85d45eaa0c32b54a90163f7, State: Initialized, Role: FOLLOWER
I20260812 06:20:01.127287 26179 consensus_queue.cc:260] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [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: "a4a397ead85d45eaa0c32b54a90163f7" member_type: VOTER }
I20260812 06:20:01.127377 26179 raft_consensus.cc:399] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:01.127401 26179 raft_consensus.cc:493] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:01.127432 26179 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:01.128095 26179 raft_consensus.cc:515] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4a397ead85d45eaa0c32b54a90163f7" member_type: VOTER }
I20260812 06:20:01.128204 26179 leader_election.cc:304] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [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: a4a397ead85d45eaa0c32b54a90163f7; no voters: 
I20260812 06:20:01.128355 26179 leader_election.cc:290] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:01.128516 26183 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:01.128712 26183 raft_consensus.cc:697] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 1 LEADER]: Becoming Leader. State: Replica: a4a397ead85d45eaa0c32b54a90163f7, State: Running, Role: LEADER
I20260812 06:20:01.128875 26179 sys_catalog.cc:565] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:01.128877 26183 consensus_queue.cc:237] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [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: "a4a397ead85d45eaa0c32b54a90163f7" member_type: VOTER }
I20260812 06:20:01.129403 26186 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a4a397ead85d45eaa0c32b54a90163f7. Latest consensus state: current_term: 1 leader_uuid: "a4a397ead85d45eaa0c32b54a90163f7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4a397ead85d45eaa0c32b54a90163f7" member_type: VOTER } }
I20260812 06:20:01.129388 26184 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a4a397ead85d45eaa0c32b54a90163f7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4a397ead85d45eaa0c32b54a90163f7" member_type: VOTER } }
I20260812 06:20:01.129503 26186 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:01.129513 26184 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:01.129803 26192 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:01.130589 26192 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:01.131179 25766 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:01.132416 26192 catalog_manager.cc:1383] Generated new cluster ID: 72d8bbedd8ab49ce9e176b0bb9973791
I20260812 06:20:01.132475 26192 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:01.146503 26192 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:01.147188 26192 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:01.160409 26192 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7: Generated new TSK 0
I20260812 06:20:01.160637 26192 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:01.163487 25766 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:01.165483 26214 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:20:01.165514 26216 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:20:01.165618 25766 server_base.cc:1061] running on GCE node
W20260812 06:20:01.165517 26213 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:20:01.165922 25766 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:01.165967 25766 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:20:01.165983 25766 hybrid_clock.cc:648] HybridClock initialized: now 1786515601165983 us; error 0 us; skew 500 ppm
I20260812 06:20:01.167054 25766 webserver.cc:533] Webserver started at http://127.25.41.129:36299/ using document root <none> and password file <none>
I20260812 06:20:01.167261 25766 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:01.167337 25766 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:01.167430 25766 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:01.167872 25766 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/instance:
uuid: "b55fcd9a5fc243d2b3005eba37b52fc6"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-ffrd"
I20260812 06:20:01.169562 25766 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:01.170629 26227 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:20:01.170914 25766 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:01.171011 25766 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root
uuid: "b55fcd9a5fc243d2b3005eba37b52fc6"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-ffrd"
I20260812 06:20:01.171105 25766 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-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:20:01.184396 25766 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:01.184803 25766 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:01.185210 25766 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:01.185688 25766 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:01.185750 25766 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:01.185811 25766 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:01.185858 25766 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:01.190138 25766 rpc_server.cc:307] RPC server started. Bound to: 127.25.41.129:37743
I20260812 06:20:01.190181 26334 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.41.129:37743 every 8 connection(s)
I20260812 06:20:01.198625 26337 heartbeater.cc:344] Connected to a master server at 127.25.41.190:39993
I20260812 06:20:01.198767 26337 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:01.199029 26337 heartbeater.cc:507] Master 127.25.41.190:39993 requested a full tablet report, sending...
I20260812 06:20:01.199738 26116 ts_manager.cc:194] Registered new tserver with Master: b55fcd9a5fc243d2b3005eba37b52fc6 (127.25.41.129:37743)
I20260812 06:20:01.200503 26116 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40958
I20260812 06:20:01.200685 25766 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010080842s
I20260812 06:20:01.208194 26116 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40970:
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:20:01.217840 26271 tablet_service.cc:1511] Processing CreateTablet for tablet b2a5043c534c4515aead8b647297b724 (DEFAULT_TABLE table=heavy-update-compaction-test [id=98a49feea14e48eea9e8943607a14a20]), partition=
I20260812 06:20:01.218149 26271 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b2a5043c534c4515aead8b647297b724. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:01.220476 26351 tablet_bootstrap.cc:492] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Bootstrap starting.
I20260812 06:20:01.221498 26351 tablet_bootstrap.cc:654] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:01.222744 26351 tablet_bootstrap.cc:492] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: No bootstrap required, opened a new log
I20260812 06:20:01.222875 26351 ts_tablet_manager.cc:1403] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:01.223315 26351 raft_consensus.cc:359] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b55fcd9a5fc243d2b3005eba37b52fc6" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 37743 } }
I20260812 06:20:01.223526 26351 raft_consensus.cc:385] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:01.223627 26351 raft_consensus.cc:740] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b55fcd9a5fc243d2b3005eba37b52fc6, State: Initialized, Role: FOLLOWER
I20260812 06:20:01.223805 26351 consensus_queue.cc:260] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [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: "b55fcd9a5fc243d2b3005eba37b52fc6" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 37743 } }
I20260812 06:20:01.223927 26351 raft_consensus.cc:399] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:01.223984 26351 raft_consensus.cc:493] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:01.224040 26351 raft_consensus.cc:3060] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:01.224887 26351 raft_consensus.cc:515] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b55fcd9a5fc243d2b3005eba37b52fc6" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 37743 } }
I20260812 06:20:01.225098 26351 leader_election.cc:304] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [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: b55fcd9a5fc243d2b3005eba37b52fc6; no voters: 
I20260812 06:20:01.225329 26351 leader_election.cc:290] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:01.225455 26354 raft_consensus.cc:2804] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:01.225711 26354 raft_consensus.cc:697] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 1 LEADER]: Becoming Leader. State: Replica: b55fcd9a5fc243d2b3005eba37b52fc6, State: Running, Role: LEADER
I20260812 06:20:01.225716 26351 ts_tablet_manager.cc:1434] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:01.225719 26337 heartbeater.cc:499] Master 127.25.41.190:39993 was elected leader, sending a full tablet report...
I20260812 06:20:01.225947 26354 consensus_queue.cc:237] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [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: "b55fcd9a5fc243d2b3005eba37b52fc6" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 37743 } }
I20260812 06:20:01.227325 26116 catalog_manager.cc:5719] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 reported cstate change: term changed from 0 to 1, leader changed from <none> to b55fcd9a5fc243d2b3005eba37b52fc6 (127.25.41.129). New cstate: current_term: 1 leader_uuid: "b55fcd9a5fc243d2b3005eba37b52fc6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b55fcd9a5fc243d2b3005eba37b52fc6" member_type: VOTER last_known_addr { host: "127.25.41.129" port: 37743 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:01.290632 25766 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.008s
I20260812 06:20:01.441201 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushMRSOp(b2a5043c534c4515aead8b647297b724): perf score=19.054940
I20260812 06:20:01.595584 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushMRSOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.154s	user 0.112s	sys 0.040s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":697,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41367,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:01.596256 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling LogGCOp(b2a5043c534c4515aead8b647297b724): free 20743880 bytes of WAL
I20260812 06:20:01.596494 26235 log_reader.cc:385] T b2a5043c534c4515aead8b647297b724: removed 2 log segments from log reader
I20260812 06:20:01.596540 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000001 (ops 1-6)
I20260812 06:20:01.596572 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000002 (ops 7-11)
I20260812 06:20:01.601583 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: LogGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:01.602193 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724): 16411393 bytes on disk
I20260812 06:20:01.602831 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.603300 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:01.617393 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.617956 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:01.777271 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.159s	user 0.097s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":631,"lbm_read_time_us":10296,"lbm_reads_lt_1ms":460,"lbm_write_time_us":28432,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":394,"threads_started":5,"update_count":2000}
I20260812 06:20:01.778828 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=13.103000
I20260812 06:20:01.824587 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.046s	user 0.019s	sys 0.022s Metrics: {"bytes_written":14645857,"delete_count":0,"lbm_write_time_us":20895,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":359,"reinsert_count":0,"update_count":1785}
I20260812 06:20:01.825194 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=1.196750
I20260812 06:20:01.842967 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.018s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2174483,"delete_count":0,"lbm_write_time_us":3054,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:20:01.843449 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:01.853140 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.853571 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:02.050432 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.197s	user 0.148s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1203,"lbm_read_time_us":16140,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32008,"lbm_writes_lt_1ms":543,"mutex_wait_us":616,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:20:02.051172 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:02.103500 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.052s	user 0.018s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21877,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:02.103981 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:02.270884 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.167s	user 0.105s	sys 0.055s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":211,"lbm_read_time_us":11065,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28467,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:20:02.271551 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:02.325419 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.053s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:02.325903 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:02.338977 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.339437 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:02.528685 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.189s	user 0.143s	sys 0.033s 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":314,"lbm_read_time_us":13756,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27992,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:02.529460 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:02.584034 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.054s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22705,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.584539 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:02.597288 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.597735 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:02.760927 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.163s	user 0.127s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":12351,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33044,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:20:02.761569 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=11.118625
I20260812 06:20:02.799804 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.038s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":17011,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:02.800375 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:02.815263 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4911,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:02.815858 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:02.942227 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.126s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":10301,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23834,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:20:02.943013 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=10.126437
I20260812 06:20:02.991549 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.048s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19298,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.992215 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:03.008177 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.008810 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushMRSOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:03.039000 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushMRSOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.030s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1188,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1663,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:03.039654 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling LogGCOp(b2a5043c534c4515aead8b647297b724): free 128867447 bytes of WAL
I20260812 06:20:03.039927 26235 log_reader.cc:385] T b2a5043c534c4515aead8b647297b724: removed 13 log segments from log reader
I20260812 06:20:03.039974 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000003 (ops 12-16)
I20260812 06:20:03.040004 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000004 (ops 17-21)
I20260812 06:20:03.040048 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000005 (ops 22-26)
I20260812 06:20:03.040091 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000006 (ops 27-31)
I20260812 06:20:03.040133 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000007 (ops 32-36)
I20260812 06:20:03.040175 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000008 (ops 37-40)
I20260812 06:20:03.040213 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000009 (ops 41-45)
I20260812 06:20:03.040252 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000010 (ops 46-50)
I20260812 06:20:03.040290 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000011 (ops 51-54)
I20260812 06:20:03.040329 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000012 (ops 55-59)
I20260812 06:20:03.040369 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000013 (ops 60-64)
I20260812 06:20:03.040407 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000014 (ops 65-68)
I20260812 06:20:03.040445 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000015 (ops 69-73)
I20260812 06:20:03.070498 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: LogGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:03.070906 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=3.181125
I20260812 06:20:03.083992 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4680,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:03.084420 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:03.094523 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.094956 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724): 483 bytes on disk
I20260812 06:20:03.095371 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.095831 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:03.270139 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.174s	user 0.121s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":734,"lbm_read_time_us":13559,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33705,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:03.270836 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:03.313949 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.043s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19479,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.314465 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:03.327261 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.327826 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:03.498256 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.170s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":353,"lbm_read_time_us":11819,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31780,"lbm_writes_lt_1ms":543,"mutex_wait_us":110,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2500}
I20260812 06:20:03.498878 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:03.557565 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.059s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24548,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.558079 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:03.701743 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.143s	user 0.075s	sys 0.068s 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":151,"lbm_read_time_us":11081,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23193,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:03.702399 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:03.752458 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.050s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22659,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.753109 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:03.766151 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.766598 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:03.956239 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.189s	user 0.117s	sys 0.066s 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":1162,"lbm_read_time_us":14310,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29890,"lbm_writes_lt_1ms":543,"mutex_wait_us":415,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:03.956841 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:04.008507 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.051s	user 0.013s	sys 0.034s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23428,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.009141 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:04.027225 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.018s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5601,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.027705 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:04.182273 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.154s	user 0.116s	sys 0.038s 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":918,"lbm_read_time_us":11439,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30464,"lbm_writes_lt_1ms":543,"mutex_wait_us":317,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:04.183027 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:04.233239 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.050s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23815,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.233767 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:04.254024 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.020s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.254494 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:04.408597 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.154s	user 0.107s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":10720,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32266,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:20:04.409384 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=14.095187
I20260812 06:20:04.462538 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.053s	user 0.020s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23149,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.463080 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:04.475394 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.475839 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushMRSOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:04.510493 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushMRSOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1176,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2163,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:04.511258 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling LogGCOp(b2a5043c534c4515aead8b647297b724): free 124257263 bytes of WAL
I20260812 06:20:04.511616 26235 log_reader.cc:385] T b2a5043c534c4515aead8b647297b724: removed 12 log segments from log reader
I20260812 06:20:04.511714 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000016 (ops 74-78)
I20260812 06:20:04.511775 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000017 (ops 79-83)
I20260812 06:20:04.511824 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000018 (ops 84-88)
I20260812 06:20:04.511861 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000019 (ops 89-93)
I20260812 06:20:04.511905 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000020 (ops 94-98)
I20260812 06:20:04.511929 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000021 (ops 99-102)
I20260812 06:20:04.511951 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000022 (ops 103-107)
I20260812 06:20:04.511982 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000023 (ops 108-112)
I20260812 06:20:04.512022 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000024 (ops 113-117)
I20260812 06:20:04.512105 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000025 (ops 118-122)
I20260812 06:20:04.512143 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000026 (ops 123-127)
I20260812 06:20:04.512166 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000027 (ops 128-132)
I20260812 06:20:04.541987 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: LogGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:04.542428 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=6.157687
I20260812 06:20:04.584133 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.041s	user 0.014s	sys 0.024s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":12708,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:04.584605 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:04.815812 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.231s	user 0.159s	sys 0.072s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979632,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":468,"lbm_read_time_us":16787,"lbm_reads_lt_1ms":765,"lbm_write_time_us":41551,"lbm_writes_lt_1ms":743,"mutex_wait_us":40,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:20:04.816538 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724): 482 bytes on disk
I20260812 06:20:04.817134 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.817991 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=18.063937
I20260812 06:20:04.890654 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.072s	user 0.035s	sys 0.036s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":32985,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.891568 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:04.910066 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.018s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.910591 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:05.151321 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.240s	user 0.153s	sys 0.086s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":16144,"lbm_reads_lt_1ms":664,"lbm_write_time_us":39157,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":3000}
I20260812 06:20:05.153442 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=18.063937
I20260812 06:20:05.227373 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.074s	user 0.032s	sys 0.025s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26744,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:05.227880 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:05.242807 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.243291 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:05.456557 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.213s	user 0.153s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1060,"lbm_read_time_us":15869,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35456,"lbm_writes_lt_1ms":643,"mutex_wait_us":312,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":3000}
I20260812 06:20:05.457502 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=16.079562
I20260812 06:20:05.525851 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.068s	user 0.032s	sys 0.020s Metrics: {"bytes_written":17968823,"delete_count":0,"lbm_write_time_us":24603,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:20:05.526378 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=5.165500
I20260812 06:20:05.552534 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.026s	user 0.005s	sys 0.013s Metrics: {"bytes_written":6646162,"delete_count":0,"lbm_write_time_us":8709,"lbm_writes_lt_1ms":165,"reinsert_count":0,"update_count":810}
I20260812 06:20:05.553117 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:05.773813 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.220s	user 0.130s	sys 0.085s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":680,"lbm_read_time_us":16757,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37955,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":3000}
I20260812 06:20:05.774361 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=16.079562
I20260812 06:20:05.831811 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.057s	user 0.031s	sys 0.021s Metrics: {"bytes_written":17886771,"delete_count":0,"lbm_write_time_us":24849,"lbm_writes_lt_1ms":439,"reinsert_count":0,"update_count":2180}
I20260812 06:20:05.832461 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=1.196750
I20260812 06:20:05.843847 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.011s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3036009,"delete_count":0,"lbm_write_time_us":3198,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:20:05.844328 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:05.855171 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.855625 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:06.064643 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.209s	user 0.160s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877185,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":361,"lbm_read_time_us":15676,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35564,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":3000}
I20260812 06:20:06.065423 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=17.071750
I20260812 06:20:06.134779 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.069s	user 0.037s	sys 0.019s Metrics: {"bytes_written":18830325,"delete_count":0,"lbm_write_time_us":25974,"lbm_writes_lt_1ms":462,"reinsert_count":0,"update_count":2295}
I20260812 06:20:06.135290 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=4.173312
I20260812 06:20:06.151968 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":5784660,"delete_count":0,"lbm_write_time_us":7154,"lbm_writes_lt_1ms":144,"reinsert_count":0,"update_count":705}
I20260812 06:20:06.152485 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushMRSOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:06.182986 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushMRSOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":1050,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2237,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:06.183837 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling LogGCOp(b2a5043c534c4515aead8b647297b724): free 129320790 bytes of WAL
I20260812 06:20:06.184149 26235 log_reader.cc:385] T b2a5043c534c4515aead8b647297b724: removed 13 log segments from log reader
I20260812 06:20:06.184211 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000028 (ops 133-137)
I20260812 06:20:06.184252 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000029 (ops 138-142)
I20260812 06:20:06.184276 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000030 (ops 143-147)
I20260812 06:20:06.184306 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000031 (ops 148-152)
I20260812 06:20:06.184346 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000032 (ops 153-156)
I20260812 06:20:06.184383 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000033 (ops 157-161)
I20260812 06:20:06.184423 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000034 (ops 162-166)
I20260812 06:20:06.184459 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000035 (ops 167-171)
I20260812 06:20:06.184518 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000036 (ops 172-176)
I20260812 06:20:06.184544 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000037 (ops 177-180)
I20260812 06:20:06.184576 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000038 (ops 181-185)
I20260812 06:20:06.184602 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000039 (ops 186-190)
I20260812 06:20:06.184638 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000040 (ops 191-195)
I20260812 06:20:06.219544 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: LogGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:20:06.220000 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724): 493 bytes on disk
I20260812 06:20:06.221490 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: UndoDeltaBlockGCOp(b2a5043c534c4515aead8b647297b724) 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:20:06.222213 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=3.181125
I20260812 06:20:06.234642 25766 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.944s	user 1.818s	sys 0.155s
I20260812 06:20:06.236294 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:06.236896 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling LogGCOp(b2a5043c534c4515aead8b647297b724): free 12017962 bytes of WAL
I20260812 06:20:06.237166 26235 log_reader.cc:385] T b2a5043c534c4515aead8b647297b724: removed 1 log segments from log reader
I20260812 06:20:06.237228 26235 log.cc:1079] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: Deleting log segment in path: /tmp/dist-test-task3JSBiT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515595469890-25766-0/minicluster-data/ts-0-root/wals/b2a5043c534c4515aead8b647297b724/wal-000000041 (ops 196-200)
I20260812 06:20:06.240630 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: LogGCOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:06.241024 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724): perf score=2.188937
I20260812 06:20:06.256727 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: FlushDeltaMemStoresOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6047,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.257333 26338 maintenance_manager.cc:419] P b55fcd9a5fc243d2b3005eba37b52fc6: Scheduling MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724): perf score=1.000000
I20260812 06:20:06.333003 25766 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.003s	sys 0.000s
I20260812 06:20:06.333523 25766 tablet_server.cc:179] TabletServer@127.25.41.129:0 shutting down...
I20260812 06:20:06.442205 26235 maintenance_manager.cc:643] P b55fcd9a5fc243d2b3005eba37b52fc6: MajorDeltaCompactionOp(b2a5043c534c4515aead8b647297b724) complete. Timing: real 0.185s	user 0.136s	sys 0.048s Metrics: {"cfile_cache_hit":302,"cfile_cache_hit_bytes":12271967,"cfile_cache_miss":532,"cfile_cache_miss_bytes":24810188,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":937,"lbm_read_time_us":11944,"lbm_reads_lt_1ms":564,"lbm_write_time_us":38535,"lbm_writes_lt_1ms":843,"mutex_wait_us":118,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":75776,"thread_start_us":77,"threads_started":1,"update_count":4000}
I20260812 06:20:06.442930 25766 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:06.443269 25766 tablet_replica.cc:333] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6: stopping tablet replica
I20260812 06:20:06.443507 25766 raft_consensus.cc:2243] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:06.443694 25766 raft_consensus.cc:2272] T b2a5043c534c4515aead8b647297b724 P b55fcd9a5fc243d2b3005eba37b52fc6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:06.449426 25766 tablet_server.cc:196] TabletServer@127.25.41.129:0 shutdown complete.
I20260812 06:20:06.514190 25766 master.cc:562] Master@127.25.41.190:39993 shutting down...
I20260812 06:20:06.517505 25766 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:06.517700 25766 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:06.517784 25766 tablet_replica.cc:333] T 00000000000000000000000000000000 P a4a397ead85d45eaa0c32b54a90163f7: stopping tablet replica
I20260812 06:20:06.530135 25766 master.cc:584] Master@127.25.41.190:39993 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5544 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11140 ms total)

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