[==========] 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:16:54.876041 14900 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.141.62:37235
I20260812 06:16:54.877046 14900 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:16:54.877662 14900 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:54.884198 14907 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:16:54.884208 14914 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:16:54.884369 14900 server_base.cc:1061] running on GCE node
W20260812 06:16:54.884650 14911 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:54.885179 14900 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:54.885293 14900 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:16:54.885329 14900 hybrid_clock.cc:648] HybridClock initialized: now 1786515414885328 us; error 0 us; skew 500 ppm
I20260812 06:16:54.887259 14900 webserver.cc:533] Webserver started at http://127.14.141.62:40571/ using document root <none> and password file <none>
I20260812 06:16:54.887871 14900 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:54.887941 14900 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:54.888161 14900 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:54.889751 14900 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/master-0-root/instance:
uuid: "8bb6c72885954936969fc1e589d784e6"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-mjjr"
I20260812 06:16:54.893383 14900 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:54.895489 14927 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:16:54.896523 14900 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:54.896663 14900 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/master-0-root
uuid: "8bb6c72885954936969fc1e589d784e6"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-mjjr"
I20260812 06:16:54.896771 14900 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-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:16:54.913214 14900 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:54.913888 14900 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:16:54.914086 14900 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:54.922331 14900 rpc_server.cc:307] RPC server started. Bound to: 127.14.141.62:37235
I20260812 06:16:54.922334 15027 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.141.62:37235 every 8 connection(s)
I20260812 06:16:54.924698 15031 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:16:54.930162 15031 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6: Bootstrap starting.
I20260812 06:16:54.932711 15031 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:54.933634 15031 log.cc:826] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:54.935359 15031 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6: No bootstrap required, opened a new log
I20260812 06:16:54.938184 15031 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb6c72885954936969fc1e589d784e6" member_type: VOTER }
I20260812 06:16:54.938378 15031 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:54.938483 15031 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8bb6c72885954936969fc1e589d784e6, State: Initialized, Role: FOLLOWER
I20260812 06:16:54.939143 15031 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [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: "8bb6c72885954936969fc1e589d784e6" member_type: VOTER }
I20260812 06:16:54.939322 15031 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:54.939393 15031 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:54.939548 15031 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:54.940387 15031 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb6c72885954936969fc1e589d784e6" member_type: VOTER }
I20260812 06:16:54.940855 15031 leader_election.cc:304] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [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: 8bb6c72885954936969fc1e589d784e6; no voters: 
I20260812 06:16:54.941181 15031 leader_election.cc:290] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:54.941320 15036 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:54.941588 15036 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 1 LEADER]: Becoming Leader. State: Replica: 8bb6c72885954936969fc1e589d784e6, State: Running, Role: LEADER
I20260812 06:16:54.942003 15036 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [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: "8bb6c72885954936969fc1e589d784e6" member_type: VOTER }
I20260812 06:16:54.942255 15031 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:54.943874 15040 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8bb6c72885954936969fc1e589d784e6. Latest consensus state: current_term: 1 leader_uuid: "8bb6c72885954936969fc1e589d784e6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb6c72885954936969fc1e589d784e6" member_type: VOTER } }
I20260812 06:16:54.943998 15040 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:54.944301 15039 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8bb6c72885954936969fc1e589d784e6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb6c72885954936969fc1e589d784e6" member_type: VOTER } }
I20260812 06:16:54.944384 15039 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:54.944402 15054 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:54.944607 14900 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:54.946679 15054 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:54.951488 15054 catalog_manager.cc:1383] Generated new cluster ID: 5b8bdf72f643483c93af08c7229d0460
I20260812 06:16:54.951560 15054 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:54.969336 15054 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:54.970577 15054 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:54.980753 15054 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6: Generated new TSK 0
I20260812 06:16:54.981530 15054 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:55.009490 14900 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:55.012265 15073 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:16:55.012312 15067 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:16:55.012428 15068 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:55.013123 14900 server_base.cc:1061] running on GCE node
I20260812 06:16:55.013337 14900 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:55.013388 14900 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:16:55.013435 14900 hybrid_clock.cc:648] HybridClock initialized: now 1786515415013434 us; error 0 us; skew 500 ppm
I20260812 06:16:55.014386 14900 webserver.cc:533] Webserver started at http://127.14.141.1:39197/ using document root <none> and password file <none>
I20260812 06:16:55.014585 14900 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:55.014644 14900 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:55.014743 14900 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:55.015146 14900 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/instance:
uuid: "9505c98f002941fc9c38762276209097"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-mjjr"
I20260812 06:16:55.016772 14900 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:55.017748 15082 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:16:55.018009 14900 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:55.018070 14900 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root
uuid: "9505c98f002941fc9c38762276209097"
format_stamp: "Formatted at 2026-08-12 06:16:55 on dist-test-slave-mjjr"
I20260812 06:16:55.018157 14900 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-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:16:55.032476 14900 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:55.032968 14900 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:55.033491 14900 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:55.034317 14900 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:55.034368 14900 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:55.034442 14900 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:55.034487 14900 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:55.041355 14900 rpc_server.cc:307] RPC server started. Bound to: 127.14.141.1:40745
I20260812 06:16:55.041388 15205 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.141.1:40745 every 8 connection(s)
I20260812 06:16:55.051458 15208 heartbeater.cc:344] Connected to a master server at 127.14.141.62:37235
I20260812 06:16:55.051733 15208 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:55.052214 15208 heartbeater.cc:507] Master 127.14.141.62:37235 requested a full tablet report, sending...
I20260812 06:16:55.053699 14959 ts_manager.cc:194] Registered new tserver with Master: 9505c98f002941fc9c38762276209097 (127.14.141.1:40745)
I20260812 06:16:55.054363 14900 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012339009s
I20260812 06:16:55.055207 14959 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51414
I20260812 06:16:55.064019 14959 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51430:
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:16:55.078887 15130 tablet_service.cc:1511] Processing CreateTablet for tablet 3cd78f1b44804c6584256490d51944be (DEFAULT_TABLE table=heavy-update-compaction-test [id=39e1439c43c247f3a0c0afccb403d281]), partition=
I20260812 06:16:55.079393 15130 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3cd78f1b44804c6584256490d51944be. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:55.081957 15230 tablet_bootstrap.cc:492] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Bootstrap starting.
I20260812 06:16:55.082935 15230 tablet_bootstrap.cc:654] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:55.084415 15230 tablet_bootstrap.cc:492] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: No bootstrap required, opened a new log
I20260812 06:16:55.084534 15230 ts_tablet_manager.cc:1403] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:55.084982 15230 raft_consensus.cc:359] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9505c98f002941fc9c38762276209097" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 40745 } }
I20260812 06:16:55.085106 15230 raft_consensus.cc:385] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:55.085152 15230 raft_consensus.cc:740] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9505c98f002941fc9c38762276209097, State: Initialized, Role: FOLLOWER
I20260812 06:16:55.085290 15230 consensus_queue.cc:260] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [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: "9505c98f002941fc9c38762276209097" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 40745 } }
I20260812 06:16:55.085382 15230 raft_consensus.cc:399] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:55.085465 15230 raft_consensus.cc:493] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:55.085525 15230 raft_consensus.cc:3060] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:55.086409 15230 raft_consensus.cc:515] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9505c98f002941fc9c38762276209097" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 40745 } }
I20260812 06:16:55.086583 15230 leader_election.cc:304] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [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: 9505c98f002941fc9c38762276209097; no voters: 
I20260812 06:16:55.086807 15230 leader_election.cc:290] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:55.086900 15234 raft_consensus.cc:2804] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:55.087095 15234 raft_consensus.cc:697] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 1 LEADER]: Becoming Leader. State: Replica: 9505c98f002941fc9c38762276209097, State: Running, Role: LEADER
I20260812 06:16:55.087173 15230 ts_tablet_manager.cc:1434] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:55.087303 15234 consensus_queue.cc:237] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [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: "9505c98f002941fc9c38762276209097" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 40745 } }
I20260812 06:16:55.087517 15208 heartbeater.cc:499] Master 127.14.141.62:37235 was elected leader, sending a full tablet report...
I20260812 06:16:55.090272 14959 catalog_manager.cc:5719] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9505c98f002941fc9c38762276209097 (127.14.141.1). New cstate: current_term: 1 leader_uuid: "9505c98f002941fc9c38762276209097" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9505c98f002941fc9c38762276209097" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 40745 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:55.158809 14900 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.018s	sys 0.012s
I20260812 06:16:55.292457 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushMRSOp(3cd78f1b44804c6584256490d51944be): perf score=19.054940
I20260812 06:16:55.475505 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushMRSOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.183s	user 0.137s	sys 0.040s Metrics: {"bytes_written":13004904,"cfile_init":1,"compiler_manager_pool.queue_time_us":223,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":891,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45274,"lbm_writes_lt_1ms":774,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":162560,"thread_start_us":155,"threads_started":1,"update_count":1585}
I20260812 06:16:55.476836 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling LogGCOp(3cd78f1b44804c6584256490d51944be): free 20743880 bytes of WAL
I20260812 06:16:55.477159 15091 log_reader.cc:385] T 3cd78f1b44804c6584256490d51944be: removed 2 log segments from log reader
I20260812 06:16:55.477224 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000001 (ops 1-6)
I20260812 06:16:55.477274 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000002 (ops 7-11)
I20260812 06:16:55.482725 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: LogGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.006s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:16:55.483157 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be): 16411393 bytes on disk
I20260812 06:16:55.483815 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:16:55.484459 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=5.165500
I20260812 06:16:55.508169 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.024s	user 0.016s	sys 0.007s Metrics: {"bytes_written":6317976,"delete_count":0,"lbm_write_time_us":7163,"lbm_writes_lt_1ms":157,"reinsert_count":0,"update_count":770}
I20260812 06:16:55.508709 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:55.513900 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.005s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1189877,"delete_count":0,"lbm_write_time_us":1313,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:16:55.514427 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:55.701548 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.187s	user 0.131s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774752,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":496,"lbm_read_time_us":13861,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30015,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":347,"threads_started":5,"update_count":2500}
I20260812 06:16:55.702195 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=10.126437
I20260812 06:16:55.746034 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.044s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17879,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.746553 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:55.756904 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.757352 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:55.899964 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.142s	user 0.106s	sys 0.028s 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":687,"lbm_read_time_us":9693,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24549,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:16:55.900606 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=10.126437
I20260812 06:16:55.947273 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.046s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16029,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.947832 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:55.958698 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.959440 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:56.082007 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.122s	user 0.088s	sys 0.034s 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":163,"lbm_read_time_us":7784,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24856,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:16:56.082659 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=10.126437
I20260812 06:16:56.125872 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15213,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.126368 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:56.137303 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.138010 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:56.263672 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.125s	user 0.106s	sys 0.019s 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":830,"lbm_read_time_us":9662,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22559,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:16:56.264240 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=10.126437
I20260812 06:16:56.309490 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.045s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14826,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.310101 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:56.320899 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.321327 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:56.460372 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.139s	user 0.104s	sys 0.034s 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":639,"lbm_read_time_us":10675,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24304,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:16:56.460930 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=11.118625
I20260812 06:16:56.489663 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.029s	user 0.017s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12690,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:56.490186 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:56.501524 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.011s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3606,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:56.502127 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:56.624176 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.122s	user 0.103s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":821,"lbm_read_time_us":7470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24048,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:16:56.624890 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=10.126437
I20260812 06:16:56.654392 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.029s	user 0.009s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12973,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.654911 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:56.665594 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.666249 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushMRSOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:56.693940 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushMRSOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.028s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1340,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1651,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:56.694689 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling LogGCOp(3cd78f1b44804c6584256490d51944be): free 120100348 bytes of WAL
I20260812 06:16:56.694929 15091 log_reader.cc:385] T 3cd78f1b44804c6584256490d51944be: removed 12 log segments from log reader
I20260812 06:16:56.694996 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000003 (ops 12-16)
I20260812 06:16:56.695051 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000004 (ops 17-21)
I20260812 06:16:56.695108 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000005 (ops 22-26)
I20260812 06:16:56.695148 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000006 (ops 27-30)
I20260812 06:16:56.695186 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000007 (ops 31-35)
I20260812 06:16:56.695222 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000008 (ops 36-40)
I20260812 06:16:56.695259 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000009 (ops 41-44)
I20260812 06:16:56.695295 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000010 (ops 45-49)
I20260812 06:16:56.695333 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000011 (ops 50-54)
I20260812 06:16:56.695369 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000012 (ops 55-59)
I20260812 06:16:56.695403 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000013 (ops 60-64)
I20260812 06:16:56.695441 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000014 (ops 65-68)
I20260812 06:16:56.720952 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: LogGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:56.721479 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=3.181125
I20260812 06:16:56.733565 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4635980,"delete_count":0,"lbm_write_time_us":4912,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:16:56.733984 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:56.744083 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":3523,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:16:56.745041 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be): 462 bytes on disk
I20260812 06:16:56.745493 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:16:56.745947 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:56.916862 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.171s	user 0.139s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":469,"lbm_read_time_us":11019,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34556,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":116,"threads_started":1,"update_count":3000}
I20260812 06:16:56.917564 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:56.967926 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19847,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.968533 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:56.985442 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.985966 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:57.142730 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.157s	user 0.125s	sys 0.016s 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":915,"lbm_read_time_us":9075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26782,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:16:57.143241 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:57.192065 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.049s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:57.192646 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:57.208433 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.209278 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:57.362671 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.153s	user 0.106s	sys 0.045s 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":335,"lbm_read_time_us":10125,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31335,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:16:57.363277 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:57.417548 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.054s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21121,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.418119 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:57.430672 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.431197 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:57.594125 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.163s	user 0.133s	sys 0.023s 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":1300,"lbm_read_time_us":10392,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31109,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:16:57.594833 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:57.640363 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.045s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19787,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.640913 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:57.794936 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.154s	user 0.101s	sys 0.041s 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":154,"lbm_read_time_us":10833,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23272,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:16:57.795783 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:57.847836 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.052s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22281,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.848358 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:57.859949 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.860559 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:58.043783 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.183s	user 0.145s	sys 0.027s 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":723,"lbm_read_time_us":11172,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27421,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:16:58.044570 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:58.096261 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.052s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":22448,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.096794 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:58.109148 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.109615 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushMRSOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:58.141556 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushMRSOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1219,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1622,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:58.142390 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling LogGCOp(3cd78f1b44804c6584256490d51944be): free 121006440 bytes of WAL
I20260812 06:16:58.142659 15091 log_reader.cc:385] T 3cd78f1b44804c6584256490d51944be: removed 12 log segments from log reader
I20260812 06:16:58.142730 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000015 (ops 69-73)
I20260812 06:16:58.142786 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000016 (ops 74-78)
I20260812 06:16:58.142869 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000017 (ops 79-83)
I20260812 06:16:58.142905 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000018 (ops 84-88)
I20260812 06:16:58.142946 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000019 (ops 89-93)
I20260812 06:16:58.142988 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000020 (ops 94-98)
I20260812 06:16:58.143031 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000021 (ops 99-102)
I20260812 06:16:58.143072 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000022 (ops 103-107)
I20260812 06:16:58.143111 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000023 (ops 108-112)
I20260812 06:16:58.143150 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000024 (ops 113-117)
I20260812 06:16:58.143190 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000025 (ops 118-122)
I20260812 06:16:58.143229 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000026 (ops 123-127)
I20260812 06:16:58.172464 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: LogGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:58.172888 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be): 483 bytes on disk
I20260812 06:16:58.173362 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.173899 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=3.181125
I20260812 06:16:58.197356 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.023s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7178,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:58.197805 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling LogGCOp(3cd78f1b44804c6584256490d51944be): free 12017949 bytes of WAL
I20260812 06:16:58.198025 15091 log_reader.cc:385] T 3cd78f1b44804c6584256490d51944be: removed 1 log segments from log reader
I20260812 06:16:58.198068 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000027 (ops 128-132)
I20260812 06:16:58.200524 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: LogGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:58.200887 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:58.210469 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3629,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.210912 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:58.442309 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.231s	user 0.149s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":215,"lbm_read_time_us":14586,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37099,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10752,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:16:58.443074 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=18.063937
I20260812 06:16:58.511507 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.068s	user 0.035s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26626,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:58.512122 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:58.529973 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.018s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.530478 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:58.752820 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.222s	user 0.135s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":14295,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39073,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:16:58.753418 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=18.063937
I20260812 06:16:58.829859 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.076s	user 0.050s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":34787,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:58.830500 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:58.850488 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.851034 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:59.057282 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.206s	user 0.130s	sys 0.067s 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":271,"lbm_read_time_us":14448,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33999,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":3000}
I20260812 06:16:59.058013 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=18.063937
I20260812 06:16:59.129191 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.071s	user 0.043s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30977,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:59.129726 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:59.145732 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.016s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.146432 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:59.342319 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.196s	user 0.140s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":12872,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33653,"lbm_writes_lt_1ms":643,"mutex_wait_us":74,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:16:59.342895 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:59.397150 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.054s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24273,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.397634 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:59.413393 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.413854 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:59.424238 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.424655 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:59.619958 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.195s	user 0.128s	sys 0.067s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":115,"lbm_read_time_us":15188,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33251,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":3000}
I20260812 06:16:59.625578 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=14.095187
I20260812 06:16:59.678351 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.053s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26233,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.678889 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:59.705660 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.027s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.706156 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:59.716614 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3917,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.717090 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushMRSOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:59.751834 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushMRSOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.035s	user 0.033s	sys 0.002s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1178,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2199,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:59.752525 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling LogGCOp(3cd78f1b44804c6584256490d51944be): free 129320724 bytes of WAL
I20260812 06:16:59.752763 15091 log_reader.cc:385] T 3cd78f1b44804c6584256490d51944be: removed 13 log segments from log reader
I20260812 06:16:59.752810 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000028 (ops 133-137)
I20260812 06:16:59.752838 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000029 (ops 138-142)
I20260812 06:16:59.752918 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000030 (ops 143-147)
I20260812 06:16:59.752960 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000031 (ops 148-152)
I20260812 06:16:59.753001 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000032 (ops 153-157)
I20260812 06:16:59.753067 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000033 (ops 158-162)
I20260812 06:16:59.753101 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000034 (ops 163-166)
I20260812 06:16:59.753144 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000035 (ops 167-171)
I20260812 06:16:59.753177 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000036 (ops 172-176)
I20260812 06:16:59.753221 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000037 (ops 177-180)
I20260812 06:16:59.753260 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000038 (ops 181-185)
I20260812 06:16:59.753300 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000039 (ops 186-190)
I20260812 06:16:59.753340 15091 log.cc:1079] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/3cd78f1b44804c6584256490d51944be/wal-000000040 (ops 191-195)
I20260812 06:16:59.782318 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: LogGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:59.782786 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be): 492 bytes on disk
I20260812 06:16:59.783304 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: UndoDeltaBlockGCOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.783943 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=3.181125
I20260812 06:16:59.804525 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.020s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7216,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:59.804968 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be): perf score=2.188937
I20260812 06:16:59.814787 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: FlushDeltaMemStoresOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3645,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.815259 15211 maintenance_manager.cc:419] P 9505c98f002941fc9c38762276209097: Scheduling MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be): perf score=1.000000
I20260812 06:16:59.900063 14900 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.741s	user 1.765s	sys 0.118s
I20260812 06:17:00.004588 14900 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.104s	user 0.004s	sys 0.000s
I20260812 06:17:00.005355 14900 tablet_server.cc:179] TabletServer@127.14.141.1:0 shutting down...
I20260812 06:17:00.042929 15091 maintenance_manager.cc:643] P 9505c98f002941fc9c38762276209097: MajorDeltaCompactionOp(3cd78f1b44804c6584256490d51944be) complete. Timing: real 0.227s	user 0.157s	sys 0.069s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082270,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":958,"lbm_read_time_us":16621,"lbm_reads_lt_1ms":871,"lbm_write_time_us":36704,"lbm_writes_lt_1ms":843,"mutex_wait_us":231,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":88,"threads_started":1,"update_count":4000}
I20260812 06:17:00.043767 14900 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:00.044713 14900 tablet_replica.cc:333] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097: stopping tablet replica
I20260812 06:17:00.044981 14900 raft_consensus.cc:2243] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:00.045228 14900 raft_consensus.cc:2272] T 3cd78f1b44804c6584256490d51944be P 9505c98f002941fc9c38762276209097 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:00.062759 14900 tablet_server.cc:196] TabletServer@127.14.141.1:0 shutdown complete.
I20260812 06:17:00.115075 14900 master.cc:562] Master@127.14.141.62:37235 shutting down...
I20260812 06:17:00.119916 14900 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:00.120097 14900 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:00.120152 14900 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8bb6c72885954936969fc1e589d784e6: stopping tablet replica
I20260812 06:17:00.132656 14900 master.cc:584] Master@127.14.141.62:37235 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5342 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:00.218472 14900 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.141.62:36161
I20260812 06:17:00.218894 14900 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:00.221086 15266 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:00.221218 15259 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:00.221299 14900 server_base.cc:1061] running on GCE node
W20260812 06:17:00.221197 15260 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:00.221596 14900 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:00.221642 14900 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:00.221657 14900 hybrid_clock.cc:648] HybridClock initialized: now 1786515420221657 us; error 0 us; skew 500 ppm
I20260812 06:17:00.222505 14900 webserver.cc:533] Webserver started at http://127.14.141.62:37617/ using document root <none> and password file <none>
I20260812 06:17:00.222640 14900 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:00.222681 14900 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:00.222738 14900 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:00.223073 14900 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/master-0-root/instance:
uuid: "eef6fb7ccb7d4b34857ba93336f2bb56"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-mjjr"
I20260812 06:17:00.224691 14900 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:00.225636 15274 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.225880 14900 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:00.225973 14900 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/master-0-root
uuid: "eef6fb7ccb7d4b34857ba93336f2bb56"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-mjjr"
I20260812 06:17:00.226058 14900 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:00.234196 14900 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:00.234560 14900 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:00.238722 14900 rpc_server.cc:307] RPC server started. Bound to: 127.14.141.62:36161
I20260812 06:17:00.241431 15387 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.141.62:36161 every 8 connection(s)
I20260812 06:17:00.242012 15389 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:00.259490 15389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56: Bootstrap starting.
I20260812 06:17:00.260504 15389 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:00.261633 15389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56: No bootstrap required, opened a new log
I20260812 06:17:00.262076 15389 raft_consensus.cc:359] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eef6fb7ccb7d4b34857ba93336f2bb56" member_type: VOTER }
I20260812 06:17:00.262195 15389 raft_consensus.cc:385] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:00.262247 15389 raft_consensus.cc:740] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eef6fb7ccb7d4b34857ba93336f2bb56, State: Initialized, Role: FOLLOWER
I20260812 06:17:00.262406 15389 consensus_queue.cc:260] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [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: "eef6fb7ccb7d4b34857ba93336f2bb56" member_type: VOTER }
I20260812 06:17:00.262506 15389 raft_consensus.cc:399] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:00.262552 15389 raft_consensus.cc:493] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:00.262610 15389 raft_consensus.cc:3060] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:00.263329 15389 raft_consensus.cc:515] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eef6fb7ccb7d4b34857ba93336f2bb56" member_type: VOTER }
I20260812 06:17:00.263491 15389 leader_election.cc:304] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [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: eef6fb7ccb7d4b34857ba93336f2bb56; no voters: 
I20260812 06:17:00.263756 15389 leader_election.cc:290] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:00.263890 15395 raft_consensus.cc:2804] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:00.264143 15395 raft_consensus.cc:697] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 1 LEADER]: Becoming Leader. State: Replica: eef6fb7ccb7d4b34857ba93336f2bb56, State: Running, Role: LEADER
I20260812 06:17:00.264254 15389 sys_catalog.cc:565] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:00.264299 15395 consensus_queue.cc:237] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [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: "eef6fb7ccb7d4b34857ba93336f2bb56" member_type: VOTER }
I20260812 06:17:00.264744 15400 sys_catalog.cc:455] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [sys.catalog]: SysCatalogTable state changed. Reason: New leader eef6fb7ccb7d4b34857ba93336f2bb56. Latest consensus state: current_term: 1 leader_uuid: "eef6fb7ccb7d4b34857ba93336f2bb56" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eef6fb7ccb7d4b34857ba93336f2bb56" member_type: VOTER } }
I20260812 06:17:00.264837 15400 sys_catalog.cc:458] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:00.264729 15398 sys_catalog.cc:455] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "eef6fb7ccb7d4b34857ba93336f2bb56" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eef6fb7ccb7d4b34857ba93336f2bb56" member_type: VOTER } }
I20260812 06:17:00.264889 15398 sys_catalog.cc:458] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:00.265125 15405 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:00.265954 15405 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:00.266314 14900 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:00.267899 15405 catalog_manager.cc:1383] Generated new cluster ID: 62505b2233c644d2921aaace36ae7750
I20260812 06:17:00.267956 15405 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:00.290243 15405 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:00.290858 15405 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:00.296561 15405 catalog_manager.cc:6092] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56: Generated new TSK 0
I20260812 06:17:00.296765 15405 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:00.298640 14900 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:00.300796 15433 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:00.300875 15443 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:00.300969 14900 server_base.cc:1061] running on GCE node
W20260812 06:17:00.300875 15437 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:00.301277 14900 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:00.301323 14900 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:00.301339 14900 hybrid_clock.cc:648] HybridClock initialized: now 1786515420301339 us; error 0 us; skew 500 ppm
I20260812 06:17:00.302260 14900 webserver.cc:533] Webserver started at http://127.14.141.1:40541/ using document root <none> and password file <none>
I20260812 06:17:00.302451 14900 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:00.302503 14900 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:00.302604 14900 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:00.303020 14900 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/instance:
uuid: "b94c638c80d2409ca69bca2d8194b967"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-mjjr"
I20260812 06:17:00.304617 14900 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:00.305549 15451 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.305779 14900 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:00.305871 14900 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root
uuid: "b94c638c80d2409ca69bca2d8194b967"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-mjjr"
I20260812 06:17:00.305964 14900 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:00.311614 14900 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:00.312012 14900 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:00.312318 14900 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:00.312774 14900 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:00.312834 14900 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.312903 14900 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:00.312954 14900 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.317361 14900 rpc_server.cc:307] RPC server started. Bound to: 127.14.141.1:43235
I20260812 06:17:00.317397 15551 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.141.1:43235 every 8 connection(s)
I20260812 06:17:00.325762 15552 heartbeater.cc:344] Connected to a master server at 127.14.141.62:36161
I20260812 06:17:00.325871 15552 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:00.326064 15552 heartbeater.cc:507] Master 127.14.141.62:36161 requested a full tablet report, sending...
I20260812 06:17:00.326716 15310 ts_manager.cc:194] Registered new tserver with Master: b94c638c80d2409ca69bca2d8194b967 (127.14.141.1:43235)
I20260812 06:17:00.327482 15310 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57910
I20260812 06:17:00.327701 14900 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00991038s
I20260812 06:17:00.334389 15310 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57924:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:00.342777 15500 tablet_service.cc:1511] Processing CreateTablet for tablet 74445ece43f841eb8e291172925ae3d8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6947d615fac248cfb635e96e676f32c7]), partition=
I20260812 06:17:00.343079 15500 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 74445ece43f841eb8e291172925ae3d8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:00.345127 15570 tablet_bootstrap.cc:492] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Bootstrap starting.
I20260812 06:17:00.346114 15570 tablet_bootstrap.cc:654] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:00.347123 15570 tablet_bootstrap.cc:492] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: No bootstrap required, opened a new log
I20260812 06:17:00.347196 15570 ts_tablet_manager.cc:1403] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:00.347579 15570 raft_consensus.cc:359] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b94c638c80d2409ca69bca2d8194b967" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 43235 } }
I20260812 06:17:00.347712 15570 raft_consensus.cc:385] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:00.347757 15570 raft_consensus.cc:740] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b94c638c80d2409ca69bca2d8194b967, State: Initialized, Role: FOLLOWER
I20260812 06:17:00.347862 15570 consensus_queue.cc:260] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [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: "b94c638c80d2409ca69bca2d8194b967" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 43235 } }
I20260812 06:17:00.347934 15570 raft_consensus.cc:399] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:00.347956 15570 raft_consensus.cc:493] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:00.347992 15570 raft_consensus.cc:3060] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:00.348941 15570 raft_consensus.cc:515] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b94c638c80d2409ca69bca2d8194b967" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 43235 } }
I20260812 06:17:00.349056 15570 leader_election.cc:304] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [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: b94c638c80d2409ca69bca2d8194b967; no voters: 
I20260812 06:17:00.349200 15570 leader_election.cc:290] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:00.349344 15577 raft_consensus.cc:2804] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:00.349515 15552 heartbeater.cc:499] Master 127.14.141.62:36161 was elected leader, sending a full tablet report...
I20260812 06:17:00.349550 15577 raft_consensus.cc:697] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 1 LEADER]: Becoming Leader. State: Replica: b94c638c80d2409ca69bca2d8194b967, State: Running, Role: LEADER
I20260812 06:17:00.349766 15577 consensus_queue.cc:237] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [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: "b94c638c80d2409ca69bca2d8194b967" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 43235 } }
I20260812 06:17:00.349812 15570 ts_tablet_manager.cc:1434] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:00.351043 15310 catalog_manager.cc:5719] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 reported cstate change: term changed from 0 to 1, leader changed from <none> to b94c638c80d2409ca69bca2d8194b967 (127.14.141.1). New cstate: current_term: 1 leader_uuid: "b94c638c80d2409ca69bca2d8194b967" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b94c638c80d2409ca69bca2d8194b967" member_type: VOTER last_known_addr { host: "127.14.141.1" port: 43235 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:00.410750 14900 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.012s	sys 0.010s
I20260812 06:17:00.568356 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushMRSOp(74445ece43f841eb8e291172925ae3d8): perf score=19.054940
I20260812 06:17:00.743362 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushMRSOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.175s	user 0.136s	sys 0.032s Metrics: {"bytes_written":13251053,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":835,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42507,"lbm_writes_lt_1ms":780,"mutex_wait_us":918,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":2944,"update_count":1615}
I20260812 06:17:00.744020 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling LogGCOp(74445ece43f841eb8e291172925ae3d8): free 20743880 bytes of WAL
I20260812 06:17:00.744258 15457 log_reader.cc:385] T 74445ece43f841eb8e291172925ae3d8: removed 2 log segments from log reader
I20260812 06:17:00.744302 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000001 (ops 1-6)
I20260812 06:17:00.744334 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000002 (ops 7-11)
I20260812 06:17:00.749774 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: LogGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:00.750173 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:00.767489 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3569334,"delete_count":0,"lbm_write_time_us":5094,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:17:00.768018 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8): 16411396 bytes on disk
I20260812 06:17:00.768421 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.768814 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:00.778173 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3564,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.778586 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:00.948870 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.170s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774792,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":509,"lbm_read_time_us":11323,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30577,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":336,"threads_started":5,"update_count":2500}
I20260812 06:17:00.949397 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:01.004647 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.055s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22496,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.005239 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:01.016741 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.017236 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:01.163054 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.146s	user 0.117s	sys 0.028s 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":333,"lbm_read_time_us":11499,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29783,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:17:01.164597 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=10.126437
I20260812 06:17:01.199105 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14651,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.199551 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:01.214542 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.215131 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:01.344169 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.129s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":380,"lbm_read_time_us":9867,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24120,"lbm_writes_lt_1ms":443,"mutex_wait_us":103,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:01.344890 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=10.126437
I20260812 06:17:01.393566 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.048s	user 0.017s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14770,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.394237 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:01.406033 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.406579 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:01.559926 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.153s	user 0.084s	sys 0.068s 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":1191,"lbm_read_time_us":10856,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25323,"lbm_writes_lt_1ms":443,"mutex_wait_us":372,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:01.560500 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=10.126437
I20260812 06:17:01.598111 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.037s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16121,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.598603 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:01.616004 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.017s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.616439 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:01.746764 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.130s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":7631,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24129,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.747426 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=11.118625
I20260812 06:17:01.780462 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.033s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13167,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.781008 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:01.806748 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.026s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4951,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":450}
I20260812 06:17:01.807237 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:01.817279 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.817729 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:01.966867 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.149s	user 0.095s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":167,"lbm_read_time_us":9998,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29479,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:17:01.967547 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=11.118625
I20260812 06:17:02.003541 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.036s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15485,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:02.004338 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:02.018648 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4887,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:02.019359 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushMRSOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:02.050789 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushMRSOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":331,"dirs.run_wall_time_us":1473,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1411,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":2816}
I20260812 06:17:02.051795 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling LogGCOp(74445ece43f841eb8e291172925ae3d8): free 120553336 bytes of WAL
I20260812 06:17:02.052031 15457 log_reader.cc:385] T 74445ece43f841eb8e291172925ae3d8: removed 12 log segments from log reader
I20260812 06:17:02.052081 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000003 (ops 12-16)
I20260812 06:17:02.052124 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000004 (ops 17-21)
I20260812 06:17:02.052201 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000005 (ops 22-26)
I20260812 06:17:02.052237 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000006 (ops 27-31)
I20260812 06:17:02.052260 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000007 (ops 32-36)
I20260812 06:17:02.052310 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000008 (ops 37-41)
I20260812 06:17:02.052349 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000009 (ops 42-46)
I20260812 06:17:02.052376 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000010 (ops 47-50)
I20260812 06:17:02.052443 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000011 (ops 51-55)
I20260812 06:17:02.052479 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000012 (ops 56-60)
I20260812 06:17:02.052505 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000013 (ops 61-64)
I20260812 06:17:02.052534 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000014 (ops 65-69)
I20260812 06:17:02.078929 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: LogGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:02.079346 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8): 482 bytes on disk
I20260812 06:17:02.079854 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.080313 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=6.157687
I20260812 06:17:02.107774 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.027s	user 0.020s	sys 0.003s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10299,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:02.108356 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling LogGCOp(74445ece43f841eb8e291172925ae3d8): free 12017983 bytes of WAL
I20260812 06:17:02.108572 15457 log_reader.cc:385] T 74445ece43f841eb8e291172925ae3d8: removed 1 log segments from log reader
I20260812 06:17:02.108619 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000015 (ops 70-74)
I20260812 06:17:02.110926 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: LogGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:02.111244 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:02.276556 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.165s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":172,"lbm_read_time_us":12461,"lbm_reads_lt_1ms":665,"lbm_write_time_us":32923,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:17:02.277107 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=15.087375
I20260812 06:17:02.326278 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.049s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":21341,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:02.326869 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:02.348243 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.021s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.348701 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:02.359494 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3512,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:02.360137 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:02.523530 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.163s	user 0.142s	sys 0.020s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":744,"lbm_read_time_us":11961,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34172,"lbm_writes_lt_1ms":643,"mutex_wait_us":282,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":3000}
I20260812 06:17:02.524286 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:02.568048 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18546,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.568590 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:02.580307 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.580783 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:02.743237 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.162s	user 0.117s	sys 0.044s 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":142,"lbm_read_time_us":11315,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32056,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":47360,"update_count":2500}
I20260812 06:17:02.744100 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=11.118625
I20260812 06:17:02.775082 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.031s	user 0.024s	sys 0.003s Metrics: {"bytes_written":12799771,"delete_count":0,"lbm_write_time_us":13560,"lbm_writes_lt_1ms":315,"reinsert_count":0,"update_count":1560}
I20260812 06:17:02.776036 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:02.791216 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":5684,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:02.791728 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:02.957018 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.165s	user 0.118s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672254,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":10077,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29860,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.957623 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=11.118625
I20260812 06:17:02.989562 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.031s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13543,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:02.990058 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:03.005849 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5995,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.006361 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:03.139791 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.133s	user 0.103s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":134,"lbm_read_time_us":7804,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24697,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":179712,"update_count":2000}
I20260812 06:17:03.140581 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=10.126437
I20260812 06:17:03.180548 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.040s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17774,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.181159 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:03.192444 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.193084 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:03.317801 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.125s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":7758,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24371,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:17:03.318539 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=10.126437
I20260812 06:17:03.362025 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.043s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":17374,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.362617 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:03.377276 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.377918 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushMRSOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:03.410106 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushMRSOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.032s	user 0.020s	sys 0.010s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1184,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2304,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:03.410920 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling LogGCOp(74445ece43f841eb8e291172925ae3d8): free 112692377 bytes of WAL
I20260812 06:17:03.411188 15457 log_reader.cc:385] T 74445ece43f841eb8e291172925ae3d8: removed 11 log segments from log reader
I20260812 06:17:03.411262 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000016 (ops 75-79)
I20260812 06:17:03.411329 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000017 (ops 80-84)
I20260812 06:17:03.411393 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000018 (ops 85-89)
I20260812 06:17:03.411435 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000019 (ops 90-94)
I20260812 06:17:03.411476 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000020 (ops 95-99)
I20260812 06:17:03.411516 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000021 (ops 100-104)
I20260812 06:17:03.411556 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000022 (ops 105-109)
I20260812 06:17:03.411597 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000023 (ops 110-114)
I20260812 06:17:03.411657 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000024 (ops 115-119)
I20260812 06:17:03.411707 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000025 (ops 120-124)
I20260812 06:17:03.411737 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000026 (ops 125-129)
I20260812 06:17:03.436934 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: LogGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:03.437467 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8): 463 bytes on disk
I20260812 06:17:03.437987 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.438545 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:03.456524 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.018s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.457216 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:03.469959 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.470572 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:03.656102 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.185s	user 0.142s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877342,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":749,"lbm_read_time_us":13564,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37891,"lbm_writes_lt_1ms":643,"mutex_wait_us":365,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:17:03.656949 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:03.717432 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.060s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24483,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.718008 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:03.728920 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.729632 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:03.898142 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.168s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":10820,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32405,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":48128,"update_count":2500}
I20260812 06:17:03.898778 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:03.957211 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.058s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.957782 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:04.116437 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.159s	user 0.091s	sys 0.056s 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":421,"lbm_read_time_us":10707,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24564,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.117219 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:04.176401 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.059s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20887,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.176975 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:04.187776 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.188241 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:04.358569 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.170s	user 0.120s	sys 0.049s 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":216,"lbm_read_time_us":12992,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28660,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:04.359788 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:04.419080 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.059s	user 0.028s	sys 0.021s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19334,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.419708 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:04.430599 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.431061 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:04.612154 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.181s	user 0.101s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":12358,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30031,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:04.612721 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:04.667557 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.055s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.668058 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:04.688921 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.021s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.689675 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:04.879235 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.189s	user 0.119s	sys 0.069s 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":1066,"lbm_read_time_us":12673,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33101,"lbm_writes_lt_1ms":543,"mutex_wait_us":349,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:17:04.880034 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=14.095187
I20260812 06:17:04.935180 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.055s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22861,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.935784 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:04.947280 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.947904 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushMRSOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:04.984072 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushMRSOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.036s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1767,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:04.984799 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling LogGCOp(74445ece43f841eb8e291172925ae3d8): free 124710510 bytes of WAL
I20260812 06:17:04.985035 15457 log_reader.cc:385] T 74445ece43f841eb8e291172925ae3d8: removed 12 log segments from log reader
I20260812 06:17:04.985081 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000027 (ops 130-134)
I20260812 06:17:04.985111 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000028 (ops 135-139)
I20260812 06:17:04.985172 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000029 (ops 140-144)
I20260812 06:17:04.985206 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000030 (ops 145-149)
I20260812 06:17:04.985247 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000031 (ops 150-154)
I20260812 06:17:04.985288 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000032 (ops 155-159)
I20260812 06:17:04.985329 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000033 (ops 160-164)
I20260812 06:17:04.985369 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000034 (ops 165-169)
I20260812 06:17:04.985409 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000035 (ops 170-174)
I20260812 06:17:04.985448 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000036 (ops 175-179)
I20260812 06:17:04.985491 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000037 (ops 180-184)
I20260812 06:17:04.985531 15457 log.cc:1079] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: Deleting log segment in path: /tmp/dist-test-task56q4iM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414865150-14900-0/minicluster-data/ts-0-root/wals/74445ece43f841eb8e291172925ae3d8/wal-000000038 (ops 185-189)
I20260812 06:17:05.010751 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: LogGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:05.011188 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:05.031175 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.020s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.031775 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=2.188937
I20260812 06:17:05.042325 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.042881 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8): 482 bytes on disk
I20260812 06:17:05.043371 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: UndoDeltaBlockGCOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.044071 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8): perf score=1.000000
I20260812 06:17:05.199981 14900 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.789s	user 1.810s	sys 0.133s
I20260812 06:17:05.292786 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: MajorDeltaCompactionOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.248s	user 0.152s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":859,"lbm_read_time_us":15827,"lbm_reads_lt_1ms":770,"lbm_write_time_us":47103,"lbm_writes_lt_1ms":743,"mutex_wait_us":431,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:17:05.293628 15553 maintenance_manager.cc:419] P b94c638c80d2409ca69bca2d8194b967: Scheduling FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8): perf score=10.126437
I20260812 06:17:05.311405 14900 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.111s	user 0.001s	sys 0.000s
I20260812 06:17:05.312055 14900 tablet_server.cc:179] TabletServer@127.14.141.1:0 shutting down...
I20260812 06:17:05.346768 15457 maintenance_manager.cc:643] P b94c638c80d2409ca69bca2d8194b967: FlushDeltaMemStoresOp(74445ece43f841eb8e291172925ae3d8) complete. Timing: real 0.053s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14288,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.347429 14900 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:05.347714 14900 tablet_replica.cc:333] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967: stopping tablet replica
I20260812 06:17:05.347865 14900 raft_consensus.cc:2243] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:05.348102 14900 raft_consensus.cc:2272] T 74445ece43f841eb8e291172925ae3d8 P b94c638c80d2409ca69bca2d8194b967 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:05.361526 14900 tablet_server.cc:196] TabletServer@127.14.141.1:0 shutdown complete.
I20260812 06:17:05.364210 14900 master.cc:562] Master@127.14.141.62:36161 shutting down...
I20260812 06:17:05.367494 14900 raft_consensus.cc:2243] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:05.367681 14900 raft_consensus.cc:2272] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:05.367769 14900 tablet_replica.cc:333] T 00000000000000000000000000000000 P eef6fb7ccb7d4b34857ba93336f2bb56: stopping tablet replica
I20260812 06:17:05.380061 14900 master.cc:584] Master@127.14.141.62:36161 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5249 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10592 ms total)

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