[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:35.316165 19932 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.119.62:40697
I20260812 06:19:35.317260 19932 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:35.317854 19932 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:35.324887 19941 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:35.324793 19942 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:19:35.324932 19932 server_base.cc:1061] running on GCE node
W20260812 06:19:35.325209 19945 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:35.325739 19932 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:35.325875 19932 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:35.325919 19932 hybrid_clock.cc:648] HybridClock initialized: now 1786515575325917 us; error 0 us; skew 500 ppm
I20260812 06:19:35.327669 19932 webserver.cc:533] Webserver started at http://127.19.119.62:38593/ using document root <none> and password file <none>
I20260812 06:19:35.328166 19932 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:35.328220 19932 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:35.328416 19932 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:35.330139 19932 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/master-0-root/instance:
uuid: "99aac7590cc04d33beec99e21536e8e2"
format_stamp: "Formatted at 2026-08-12 06:19:35 on dist-test-slave-2kcd"
I20260812 06:19:35.333547 19932 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:35.335443 19953 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.336452 19932 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:35.336578 19932 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/master-0-root
uuid: "99aac7590cc04d33beec99e21536e8e2"
format_stamp: "Formatted at 2026-08-12 06:19:35 on dist-test-slave-2kcd"
I20260812 06:19:35.336681 19932 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:35.353873 19932 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:35.354544 19932 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:35.354730 19932 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:35.362411 19932 rpc_server.cc:307] RPC server started. Bound to: 127.19.119.62:40697
I20260812 06:19:35.362421 20050 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.119.62:40697 every 8 connection(s)
I20260812 06:19:35.364712 20052 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:35.370189 20052 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2: Bootstrap starting.
I20260812 06:19:35.372473 20052 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:35.373365 20052 log.cc:826] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:35.375010 20052 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2: No bootstrap required, opened a new log
I20260812 06:19:35.377751 20052 raft_consensus.cc:359] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "99aac7590cc04d33beec99e21536e8e2" member_type: VOTER }
I20260812 06:19:35.377916 20052 raft_consensus.cc:385] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:35.377956 20052 raft_consensus.cc:740] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 99aac7590cc04d33beec99e21536e8e2, State: Initialized, Role: FOLLOWER
I20260812 06:19:35.378592 20052 consensus_queue.cc:260] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [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: "99aac7590cc04d33beec99e21536e8e2" member_type: VOTER }
I20260812 06:19:35.378741 20052 raft_consensus.cc:399] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:35.378788 20052 raft_consensus.cc:493] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:35.378872 20052 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:35.379611 20052 raft_consensus.cc:515] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "99aac7590cc04d33beec99e21536e8e2" member_type: VOTER }
I20260812 06:19:35.379995 20052 leader_election.cc:304] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [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: 99aac7590cc04d33beec99e21536e8e2; no voters: 
I20260812 06:19:35.380280 20052 leader_election.cc:290] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:35.380436 20055 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:35.380748 20055 raft_consensus.cc:697] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 1 LEADER]: Becoming Leader. State: Replica: 99aac7590cc04d33beec99e21536e8e2, State: Running, Role: LEADER
I20260812 06:19:35.381198 20055 consensus_queue.cc:237] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [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: "99aac7590cc04d33beec99e21536e8e2" member_type: VOTER }
I20260812 06:19:35.381376 20052 sys_catalog.cc:565] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:35.383148 20057 sys_catalog.cc:455] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "99aac7590cc04d33beec99e21536e8e2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "99aac7590cc04d33beec99e21536e8e2" member_type: VOTER } }
I20260812 06:19:35.383119 20060 sys_catalog.cc:455] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 99aac7590cc04d33beec99e21536e8e2. Latest consensus state: current_term: 1 leader_uuid: "99aac7590cc04d33beec99e21536e8e2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "99aac7590cc04d33beec99e21536e8e2" member_type: VOTER } }
I20260812 06:19:35.383248 20060 sys_catalog.cc:458] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:35.383248 20057 sys_catalog.cc:458] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:35.383699 19932 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:35.383870 20081 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:35.386077 20081 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:35.390816 20081 catalog_manager.cc:1383] Generated new cluster ID: b44cb7d76f544e199030c05a6974b14c
I20260812 06:19:35.390882 20081 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:35.413506 20081 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:35.414463 20081 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:35.421132 20081 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2: Generated new TSK 0
I20260812 06:19:35.421840 20081 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:35.448647 19932 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:35.451767 20089 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:35.451869 20096 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:35.451992 20091 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:19:35.452272 19932 server_base.cc:1061] running on GCE node
I20260812 06:19:35.452451 19932 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:35.452502 19932 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:35.452538 19932 hybrid_clock.cc:648] HybridClock initialized: now 1786515575452536 us; error 0 us; skew 500 ppm
I20260812 06:19:35.453572 19932 webserver.cc:533] Webserver started at http://127.19.119.1:33451/ using document root <none> and password file <none>
I20260812 06:19:35.453748 19932 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:35.453809 19932 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:35.453902 19932 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:35.454346 19932 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/instance:
uuid: "aee0db8353de4a53a9148d1fdcff4184"
format_stamp: "Formatted at 2026-08-12 06:19:35 on dist-test-slave-2kcd"
I20260812 06:19:35.456256 19932 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:35.457427 20101 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.457719 19932 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:35.457785 19932 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root
uuid: "aee0db8353de4a53a9148d1fdcff4184"
format_stamp: "Formatted at 2026-08-12 06:19:35 on dist-test-slave-2kcd"
I20260812 06:19:35.457932 19932 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:35.472760 19932 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:35.473354 19932 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:35.473951 19932 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:35.474872 19932 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:35.474927 19932 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.474996 19932 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:35.475041 19932 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.482046 19932 rpc_server.cc:307] RPC server started. Bound to: 127.19.119.1:44945
I20260812 06:19:35.482074 20227 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.119.1:44945 every 8 connection(s)
I20260812 06:19:35.492556 20231 heartbeater.cc:344] Connected to a master server at 127.19.119.62:40697
I20260812 06:19:35.492866 20231 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:35.493417 20231 heartbeater.cc:507] Master 127.19.119.62:40697 requested a full tablet report, sending...
I20260812 06:19:35.495074 19986 ts_manager.cc:194] Registered new tserver with Master: aee0db8353de4a53a9148d1fdcff4184 (127.19.119.1:44945)
I20260812 06:19:35.495242 19932 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012388101s
I20260812 06:19:35.496363 19986 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54382
I20260812 06:19:35.506207 19986 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54390:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:35.521605 20149 tablet_service.cc:1511] Processing CreateTablet for tablet 35b0ce8371a2455bbd01686d8e8da3ee (DEFAULT_TABLE table=heavy-update-compaction-test [id=5267468f8436429e80aa45ec977dd26e]), partition=
I20260812 06:19:35.522112 20149 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 35b0ce8371a2455bbd01686d8e8da3ee. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:35.525072 20250 tablet_bootstrap.cc:492] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Bootstrap starting.
I20260812 06:19:35.526315 20250 tablet_bootstrap.cc:654] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:35.527786 20250 tablet_bootstrap.cc:492] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: No bootstrap required, opened a new log
I20260812 06:19:35.527940 20250 ts_tablet_manager.cc:1403] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:35.528684 20250 raft_consensus.cc:359] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aee0db8353de4a53a9148d1fdcff4184" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44945 } }
I20260812 06:19:35.528882 20250 raft_consensus.cc:385] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:35.528925 20250 raft_consensus.cc:740] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aee0db8353de4a53a9148d1fdcff4184, State: Initialized, Role: FOLLOWER
I20260812 06:19:35.529063 20250 consensus_queue.cc:260] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [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: "aee0db8353de4a53a9148d1fdcff4184" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44945 } }
I20260812 06:19:35.529160 20250 raft_consensus.cc:399] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:35.529194 20250 raft_consensus.cc:493] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:35.529243 20250 raft_consensus.cc:3060] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:35.530249 20250 raft_consensus.cc:515] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aee0db8353de4a53a9148d1fdcff4184" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44945 } }
I20260812 06:19:35.530421 20250 leader_election.cc:304] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [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: aee0db8353de4a53a9148d1fdcff4184; no voters: 
I20260812 06:19:35.530627 20250 leader_election.cc:290] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:35.530788 20256 raft_consensus.cc:2804] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:35.530966 20250 ts_tablet_manager.cc:1434] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:35.531118 20256 raft_consensus.cc:697] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 1 LEADER]: Becoming Leader. State: Replica: aee0db8353de4a53a9148d1fdcff4184, State: Running, Role: LEADER
I20260812 06:19:35.531214 20231 heartbeater.cc:499] Master 127.19.119.62:40697 was elected leader, sending a full tablet report...
I20260812 06:19:35.531378 20256 consensus_queue.cc:237] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [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: "aee0db8353de4a53a9148d1fdcff4184" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44945 } }
I20260812 06:19:35.534381 19986 catalog_manager.cc:5719] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 reported cstate change: term changed from 0 to 1, leader changed from <none> to aee0db8353de4a53a9148d1fdcff4184 (127.19.119.1). New cstate: current_term: 1 leader_uuid: "aee0db8353de4a53a9148d1fdcff4184" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aee0db8353de4a53a9148d1fdcff4184" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44945 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:35.601629 19932 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.016s	sys 0.012s
I20260812 06:19:35.733238 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=19.054940
I20260812 06:19:35.921197 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.188s	user 0.157s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":209,"delete_count":0,"dirs.queue_time_us":1004,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1053,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45519,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":138,"threads_started":1,"update_count":1500}
I20260812 06:19:35.922490 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee): free 20743831 bytes of WAL
I20260812 06:19:35.922859 20109 log_reader.cc:385] T 35b0ce8371a2455bbd01686d8e8da3ee: removed 2 log segments from log reader
I20260812 06:19:35.922930 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000001 (ops 1-6)
I20260812 06:19:35.922979 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000002 (ops 7-11)
I20260812 06:19:35.928900 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:19:35.929237 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee): 16411393 bytes on disk
I20260812 06:19:35.929943 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:35.930346 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=6.157687
I20260812 06:19:35.961470 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.031s	user 0.018s	sys 0.012s Metrics: {"bytes_written":7507666,"delete_count":0,"lbm_write_time_us":10892,"lbm_writes_lt_1ms":186,"reinsert_count":0,"update_count":915}
I20260812 06:19:35.962097 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:36.142475 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.180s	user 0.104s	sys 0.068s Metrics: {"cfile_cache_miss":515,"cfile_cache_miss_bytes":24077279,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":63,"lbm_read_time_us":12602,"lbm_reads_lt_1ms":543,"lbm_write_time_us":29420,"lbm_writes_lt_1ms":526,"peak_mem_usage":60337537,"reinsert_count":0,"thread_start_us":227,"threads_started":5,"update_count":2415}
I20260812 06:19:36.143009 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=15.087375
I20260812 06:19:36.202440 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.059s	user 0.029s	sys 0.027s Metrics: {"bytes_written":17107319,"delete_count":0,"lbm_write_time_us":26671,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":418,"reinsert_count":0,"update_count":2085}
I20260812 06:19:36.203263 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:36.240540 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.037s	user 0.012s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.241107 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:36.253470 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.254061 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:36.546988 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.293s	user 0.201s	sys 0.080s Metrics: {"cfile_cache_miss":650,"cfile_cache_miss_bytes":29574637,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1431,"lbm_read_time_us":16901,"lbm_reads_lt_1ms":690,"lbm_write_time_us":61277,"lbm_writes_lt_1ms":660,"mutex_wait_us":306,"peak_mem_usage":77280451,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":3085}
I20260812 06:19:36.548166 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=11.118625
I20260812 06:19:36.627521 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.079s	user 0.052s	sys 0.023s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":35690,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:36.628219 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:36.650872 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.022s	user 0.014s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7841,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":450}
I20260812 06:19:36.651747 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:36.934791 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.283s	user 0.183s	sys 0.075s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1597,"lbm_read_time_us":19126,"lbm_reads_lt_1ms":464,"lbm_write_time_us":46542,"lbm_writes_lt_1ms":443,"mutex_wait_us":702,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39296,"update_count":2000}
I20260812 06:19:36.935876 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:37.020933 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.085s	user 0.061s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":38642,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.021793 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:37.047039 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.025s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":9524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.047704 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:37.307727 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.260s	user 0.210s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":17895,"lbm_reads_lt_1ms":564,"lbm_write_time_us":51395,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:37.308843 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:37.396485 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.087s	user 0.056s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":38946,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.397455 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:37.419390 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.022s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.420105 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:37.676813 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.256s	user 0.212s	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":148,"lbm_read_time_us":19668,"lbm_reads_lt_1ms":572,"lbm_write_time_us":59039,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:37.677882 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=10.126437
I20260812 06:19:37.752964 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.075s	user 0.051s	sys 0.019s Metrics: {"bytes_written":12348515,"delete_count":0,"lbm_write_time_us":34492,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1505}
I20260812 06:19:37.753892 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:37.786908 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.033s	user 0.017s	sys 0.013s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":12752,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:37.787883 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:37.830098 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.042s	user 0.039s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":397,"dirs.run_wall_time_us":1710,"drs_written":1,"lbm_read_time_us":151,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2933,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:37.831715 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee): free 120553441 bytes of WAL
I20260812 06:19:37.832191 20109 log_reader.cc:385] T 35b0ce8371a2455bbd01686d8e8da3ee: removed 12 log segments from log reader
I20260812 06:19:37.832262 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000003 (ops 12-16)
I20260812 06:19:37.832351 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000004 (ops 17-21)
I20260812 06:19:37.832439 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000005 (ops 22-26)
I20260812 06:19:37.832504 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000006 (ops 27-30)
I20260812 06:19:37.832580 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000007 (ops 31-35)
I20260812 06:19:37.832741 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000008 (ops 36-40)
I20260812 06:19:37.832851 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000009 (ops 41-44)
I20260812 06:19:37.832944 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000010 (ops 45-49)
I20260812 06:19:37.833040 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000011 (ops 50-54)
I20260812 06:19:37.833108 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000012 (ops 55-59)
I20260812 06:19:37.833185 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000013 (ops 60-64)
I20260812 06:19:37.833253 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000014 (ops 65-69)
I20260812 06:19:37.884466 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.052s	user 0.000s	sys 0.049s Metrics: {}
I20260812 06:19:37.885201 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee): 463 bytes on disk
I20260812 06:19:37.889952 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":147,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.891043 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=4.173312
I20260812 06:19:37.920385 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.029s	user 0.017s	sys 0.009s Metrics: {"bytes_written":6276941,"delete_count":0,"lbm_write_time_us":12229,"lbm_writes_lt_1ms":156,"mutex_wait_us":134,"reinsert_count":0,"update_count":765}
I20260812 06:19:37.921170 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:37.947805 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.026s	user 0.006s	sys 0.009s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":6331,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:19:37.948576 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:38.204619 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.256s	user 0.181s	sys 0.074s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877284,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1179,"lbm_read_time_us":21812,"lbm_reads_lt_1ms":666,"lbm_write_time_us":52162,"lbm_writes_lt_1ms":643,"mutex_wait_us":9,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":686,"threads_started":6,"update_count":3000}
I20260812 06:19:38.205693 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:38.307083 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.101s	user 0.068s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":41675,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.308043 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:38.364517 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.056s	user 0.020s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":12155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.365218 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:38.384725 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.385543 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:38.730345 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.345s	user 0.250s	sys 0.094s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":406,"lbm_read_time_us":21789,"lbm_reads_lt_1ms":673,"lbm_write_time_us":88681,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"thread_start_us":221,"threads_started":4,"update_count":3000}
I20260812 06:19:38.730885 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:38.771227 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.040s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17742,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.771855 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:38.790838 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.019s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.791391 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:38.962965 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.171s	user 0.116s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":11143,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32041,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:19:38.963768 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:39.013284 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.049s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21323,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.013777 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:39.166157 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.152s	user 0.096s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672162,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":203,"lbm_read_time_us":9752,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25060,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:19:39.166742 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:39.219609 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.052s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20691,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:39.220140 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:39.230892 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.231357 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:39.409996 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.178s	user 0.129s	sys 0.043s 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":38,"lbm_read_time_us":11554,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32418,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:19:39.410625 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=11.118625
I20260812 06:19:39.445780 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15667,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.446729 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:39.464449 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.465034 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:39.608276 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.143s	user 0.108s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1100,"lbm_read_time_us":9401,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29784,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:39.609061 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=11.118625
I20260812 06:19:39.648721 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17353,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.649322 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:39.663825 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.664726 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:39.694300 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1565,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1672,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:39.695030 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee): free 124710310 bytes of WAL
I20260812 06:19:39.695266 20109 log_reader.cc:385] T 35b0ce8371a2455bbd01686d8e8da3ee: removed 12 log segments from log reader
I20260812 06:19:39.695309 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000015 (ops 70-74)
I20260812 06:19:39.695338 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000016 (ops 75-79)
I20260812 06:19:39.695412 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000017 (ops 80-84)
I20260812 06:19:39.695444 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000018 (ops 85-89)
I20260812 06:19:39.695485 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000019 (ops 90-94)
I20260812 06:19:39.695529 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000020 (ops 95-99)
I20260812 06:19:39.695567 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000021 (ops 100-104)
I20260812 06:19:39.695605 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000022 (ops 105-109)
I20260812 06:19:39.695644 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000023 (ops 110-114)
I20260812 06:19:39.695688 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000024 (ops 115-119)
I20260812 06:19:39.695727 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000025 (ops 120-124)
I20260812 06:19:39.695765 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000026 (ops 125-129)
I20260812 06:19:39.724706 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:39.725826 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee): 473 bytes on disk
I20260812 06:19:39.726488 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.727136 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=4.173312
I20260812 06:19:39.741595 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5784657,"delete_count":0,"lbm_write_time_us":5968,"lbm_writes_lt_1ms":144,"reinsert_count":0,"update_count":705}
I20260812 06:19:39.742069 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.196750
I20260812 06:19:39.751780 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":2961,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:19:39.752293 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:39.924257 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.172s	user 0.147s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877294,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":505,"lbm_read_time_us":12002,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35369,"lbm_writes_lt_1ms":643,"mutex_wait_us":98,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":138,"threads_started":1,"update_count":3000}
I20260812 06:19:39.924940 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:39.973166 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.048s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.973742 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:39.990379 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.990865 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:40.155076 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.164s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1561,"lbm_read_time_us":11632,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31554,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2500}
I20260812 06:19:40.155710 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=11.118625
I20260812 06:19:40.190755 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14705,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:40.191329 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:40.216327 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.025s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.216882 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:40.227598 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.228278 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:40.396562 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.168s	user 0.135s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":254,"lbm_read_time_us":12310,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30134,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55936,"update_count":2500}
I20260812 06:19:40.397296 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:40.452836 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.055s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21872,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.453442 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:40.464900 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.011s	user 0.011s	sys 0.000s 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:19:40.465423 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:40.639521 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.174s	user 0.101s	sys 0.072s 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":924,"lbm_read_time_us":12525,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30220,"lbm_writes_lt_1ms":543,"mutex_wait_us":201,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2500}
I20260812 06:19:40.640321 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:40.697142 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.057s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21526,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.697700 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:40.708966 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.709709 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:40.879029 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.169s	user 0.110s	sys 0.059s 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":1160,"lbm_read_time_us":12238,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29252,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.879560 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:40.936642 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.057s	user 0.021s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20883,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.937424 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:40.956089 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.956599 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:41.133214 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.176s	user 0.131s	sys 0.045s 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":1693,"lbm_read_time_us":12831,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31517,"lbm_writes_lt_1ms":543,"mutex_wait_us":481,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:19:41.134162 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=14.095187
I20260812 06:19:41.194685 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.060s	user 0.032s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23129,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.195304 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:41.206418 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.206911 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:41.246600 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushMRSOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.039s	user 0.032s	sys 0.002s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1558,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:41.247447 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee): free 128867727 bytes of WAL
I20260812 06:19:41.247697 20109 log_reader.cc:385] T 35b0ce8371a2455bbd01686d8e8da3ee: removed 13 log segments from log reader
I20260812 06:19:41.247740 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000027 (ops 130-134)
I20260812 06:19:41.247769 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000028 (ops 135-139)
I20260812 06:19:41.247830 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000029 (ops 140-144)
I20260812 06:19:41.247874 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000030 (ops 145-148)
I20260812 06:19:41.247915 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000031 (ops 149-153)
I20260812 06:19:41.247977 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000032 (ops 154-158)
I20260812 06:19:41.248008 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000033 (ops 159-162)
I20260812 06:19:41.248072 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000034 (ops 163-167)
I20260812 06:19:41.248112 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000035 (ops 168-172)
I20260812 06:19:41.248152 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000036 (ops 173-176)
I20260812 06:19:41.248193 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000037 (ops 177-181)
I20260812 06:19:41.248231 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000038 (ops 182-186)
I20260812 06:19:41.248273 20109 log.cc:1079] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/35b0ce8371a2455bbd01686d8e8da3ee/wal-000000039 (ops 187-191)
I20260812 06:19:41.275883 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: LogGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:41.276374 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee): 492 bytes on disk
I20260812 06:19:41.276916 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: UndoDeltaBlockGCOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.277766 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=3.181125
I20260812 06:19:41.291136 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4556,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:41.291604 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=2.188937
I20260812 06:19:41.301589 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3743,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.302096 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=1.000000
I20260812 06:19:41.436861 19932 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.835s	user 2.152s	sys 0.092s
I20260812 06:19:41.515218 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: MajorDeltaCompactionOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.213s	user 0.139s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15259,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38136,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:19:41.515745 20232 maintenance_manager.cc:419] P aee0db8353de4a53a9148d1fdcff4184: Scheduling FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee): perf score=10.126437
I20260812 06:19:41.542696 19932 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.105s	user 0.002s	sys 0.000s
I20260812 06:19:41.543402 19932 tablet_server.cc:179] TabletServer@127.19.119.1:0 shutting down...
I20260812 06:19:41.551628 20109 maintenance_manager.cc:643] P aee0db8353de4a53a9148d1fdcff4184: FlushDeltaMemStoresOp(35b0ce8371a2455bbd01686d8e8da3ee) complete. Timing: real 0.036s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15137,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.552207 19932 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:41.552627 19932 tablet_replica.cc:333] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184: stopping tablet replica
I20260812 06:19:41.552910 19932 raft_consensus.cc:2243] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.553161 19932 raft_consensus.cc:2272] T 35b0ce8371a2455bbd01686d8e8da3ee P aee0db8353de4a53a9148d1fdcff4184 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.568111 19932 tablet_server.cc:196] TabletServer@127.19.119.1:0 shutdown complete.
I20260812 06:19:41.577118 19932 master.cc:562] Master@127.19.119.62:40697 shutting down...
I20260812 06:19:41.580747 19932 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.581003 19932 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.581106 19932 tablet_replica.cc:333] T 00000000000000000000000000000000 P 99aac7590cc04d33beec99e21536e8e2: stopping tablet replica
I20260812 06:19:41.593452 19932 master.cc:584] Master@127.19.119.62:40697 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6373 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:41.688979 19932 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.119.62:35903
I20260812 06:19:41.689445 19932 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.691682 20306 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:19:41.691848 19932 server_base.cc:1061] running on GCE node
W20260812 06:19:41.691821 20309 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.691689 20305 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.692147 19932 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.692191 19932 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:41.692206 19932 hybrid_clock.cc:648] HybridClock initialized: now 1786515581692206 us; error 0 us; skew 500 ppm
I20260812 06:19:41.693161 19932 webserver.cc:533] Webserver started at http://127.19.119.62:37779/ using document root <none> and password file <none>
I20260812 06:19:41.693347 19932 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.693394 19932 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.693495 19932 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.693917 19932 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/master-0-root/instance:
uuid: "f9b30c7db5f244a7ad13509246df7787"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-2kcd"
I20260812 06:19:41.695462 19932 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:41.696480 20316 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.696884 19932 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:41.696954 19932 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/master-0-root
uuid: "f9b30c7db5f244a7ad13509246df7787"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-2kcd"
I20260812 06:19:41.697043 19932 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:41.713909 19932 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.714365 19932 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.718822 19932 rpc_server.cc:307] RPC server started. Bound to: 127.19.119.62:35903
I20260812 06:19:41.721954 20409 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.119.62:35903 every 8 connection(s)
I20260812 06:19:41.722592 20410 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.737557 20410 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787: Bootstrap starting.
I20260812 06:19:41.738350 20410 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.739495 20410 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787: No bootstrap required, opened a new log
I20260812 06:19:41.739893 20410 raft_consensus.cc:359] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9b30c7db5f244a7ad13509246df7787" member_type: VOTER }
I20260812 06:19:41.739981 20410 raft_consensus.cc:385] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.740005 20410 raft_consensus.cc:740] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f9b30c7db5f244a7ad13509246df7787, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.740159 20410 consensus_queue.cc:260] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [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: "f9b30c7db5f244a7ad13509246df7787" member_type: VOTER }
I20260812 06:19:41.740252 20410 raft_consensus.cc:399] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.740276 20410 raft_consensus.cc:493] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.740306 20410 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.741084 20410 raft_consensus.cc:515] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9b30c7db5f244a7ad13509246df7787" member_type: VOTER }
I20260812 06:19:41.741202 20410 leader_election.cc:304] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [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: f9b30c7db5f244a7ad13509246df7787; no voters: 
I20260812 06:19:41.741359 20410 leader_election.cc:290] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.741534 20416 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.741721 20416 raft_consensus.cc:697] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 1 LEADER]: Becoming Leader. State: Replica: f9b30c7db5f244a7ad13509246df7787, State: Running, Role: LEADER
I20260812 06:19:41.741866 20410 sys_catalog.cc:565] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:41.741899 20416 consensus_queue.cc:237] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [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: "f9b30c7db5f244a7ad13509246df7787" member_type: VOTER }
I20260812 06:19:41.742364 20419 sys_catalog.cc:455] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f9b30c7db5f244a7ad13509246df7787" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9b30c7db5f244a7ad13509246df7787" member_type: VOTER } }
I20260812 06:19:41.742381 20422 sys_catalog.cc:455] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f9b30c7db5f244a7ad13509246df7787. Latest consensus state: current_term: 1 leader_uuid: "f9b30c7db5f244a7ad13509246df7787" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9b30c7db5f244a7ad13509246df7787" member_type: VOTER } }
I20260812 06:19:41.742491 20422 sys_catalog.cc:458] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.742764 20419 sys_catalog.cc:458] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.742803 20426 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:41.743983 20426 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:41.744272 19932 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:41.745790 20426 catalog_manager.cc:1383] Generated new cluster ID: 249005c068734af49711e1d743dfb53c
I20260812 06:19:41.745872 20426 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:41.752847 20426 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:41.753319 20426 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:41.761533 20426 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787: Generated new TSK 0
I20260812 06:19:41.761659 20426 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:41.776712 19932 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.778981 20447 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.778981 20454 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.779012 20446 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.779161 19932 server_base.cc:1061] running on GCE node
I20260812 06:19:41.779384 19932 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.779426 19932 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:41.779448 19932 hybrid_clock.cc:648] HybridClock initialized: now 1786515581779448 us; error 0 us; skew 500 ppm
I20260812 06:19:41.780336 19932 webserver.cc:533] Webserver started at http://127.19.119.1:45395/ using document root <none> and password file <none>
I20260812 06:19:41.780488 19932 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.780532 19932 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.780596 19932 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.781035 19932 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/instance:
uuid: "407b384e135d4a13865b9cef6cfa203b"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-2kcd"
I20260812 06:19:41.782526 19932 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:41.783427 20462 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.783708 19932 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:41.783775 19932 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root
uuid: "407b384e135d4a13865b9cef6cfa203b"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-2kcd"
I20260812 06:19:41.783833 19932 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:41.791733 19932 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.792035 19932 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.792273 19932 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:41.792768 19932 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:41.792866 19932 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.792938 19932 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:41.792984 19932 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.797334 19932 rpc_server.cc:307] RPC server started. Bound to: 127.19.119.1:44983
I20260812 06:19:41.797364 20593 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.119.1:44983 every 8 connection(s)
I20260812 06:19:41.806442 20594 heartbeater.cc:344] Connected to a master server at 127.19.119.62:35903
I20260812 06:19:41.806607 20594 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:41.806883 20594 heartbeater.cc:507] Master 127.19.119.62:35903 requested a full tablet report, sending...
I20260812 06:19:41.807636 20355 ts_manager.cc:194] Registered new tserver with Master: 407b384e135d4a13865b9cef6cfa203b (127.19.119.1:44983)
I20260812 06:19:41.807770 19932 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009973513s
I20260812 06:19:41.808506 20355 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50266
I20260812 06:19:41.814893 20355 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50274:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:41.823735 20517 tablet_service.cc:1511] Processing CreateTablet for tablet 04467b9743d14ac1a6add337aaa499b4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=141eda3efde0459caf306f367d6dbf8e]), partition=
I20260812 06:19:41.824043 20517 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 04467b9743d14ac1a6add337aaa499b4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.826359 20619 tablet_bootstrap.cc:492] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Bootstrap starting.
I20260812 06:19:41.827214 20619 tablet_bootstrap.cc:654] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.828287 20619 tablet_bootstrap.cc:492] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: No bootstrap required, opened a new log
I20260812 06:19:41.828374 20619 ts_tablet_manager.cc:1403] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:41.828754 20619 raft_consensus.cc:359] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "407b384e135d4a13865b9cef6cfa203b" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44983 } }
I20260812 06:19:41.828929 20619 raft_consensus.cc:385] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.829001 20619 raft_consensus.cc:740] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 407b384e135d4a13865b9cef6cfa203b, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.829176 20619 consensus_queue.cc:260] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [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: "407b384e135d4a13865b9cef6cfa203b" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44983 } }
I20260812 06:19:41.829283 20619 raft_consensus.cc:399] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.829329 20619 raft_consensus.cc:493] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.829382 20619 raft_consensus.cc:3060] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.830150 20619 raft_consensus.cc:515] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "407b384e135d4a13865b9cef6cfa203b" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44983 } }
I20260812 06:19:41.830313 20619 leader_election.cc:304] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [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: 407b384e135d4a13865b9cef6cfa203b; no voters: 
I20260812 06:19:41.830518 20619 leader_election.cc:290] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.830655 20621 raft_consensus.cc:2804] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.830900 20594 heartbeater.cc:499] Master 127.19.119.62:35903 was elected leader, sending a full tablet report...
I20260812 06:19:41.830868 20619 ts_tablet_manager.cc:1434] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:41.830884 20621 raft_consensus.cc:697] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 1 LEADER]: Becoming Leader. State: Replica: 407b384e135d4a13865b9cef6cfa203b, State: Running, Role: LEADER
I20260812 06:19:41.831084 20621 consensus_queue.cc:237] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [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: "407b384e135d4a13865b9cef6cfa203b" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44983 } }
I20260812 06:19:41.832371 20355 catalog_manager.cc:5719] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b reported cstate change: term changed from 0 to 1, leader changed from <none> to 407b384e135d4a13865b9cef6cfa203b (127.19.119.1). New cstate: current_term: 1 leader_uuid: "407b384e135d4a13865b9cef6cfa203b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "407b384e135d4a13865b9cef6cfa203b" member_type: VOTER last_known_addr { host: "127.19.119.1" port: 44983 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:41.895187 19932 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.013s	sys 0.010s
I20260812 06:19:42.048487 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushMRSOp(04467b9743d14ac1a6add337aaa499b4): perf score=19.054940
I20260812 06:19:42.203547 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushMRSOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.155s	user 0.127s	sys 0.024s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":986,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38779,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:42.204514 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling LogGCOp(04467b9743d14ac1a6add337aaa499b4): free 20743880 bytes of WAL
I20260812 06:19:42.204834 20474 log_reader.cc:385] T 04467b9743d14ac1a6add337aaa499b4: removed 2 log segments from log reader
I20260812 06:19:42.204909 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000001 (ops 1-6)
I20260812 06:19:42.204978 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000002 (ops 7-11)
I20260812 06:19:42.209702 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: LogGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:42.210137 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4): 16411392 bytes on disk
I20260812 06:19:42.210590 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4) 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:19:42.211202 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:42.234300 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.234794 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:42.245666 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.246174 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:42.419351 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.173s	user 0.114s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":559,"lbm_read_time_us":13051,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29608,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":341,"threads_started":5,"update_count":2500}
I20260812 06:19:42.420159 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:42.473697 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.053s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.474169 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:42.485972 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.486547 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:42.657395 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.171s	user 0.124s	sys 0.035s 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":1308,"lbm_read_time_us":9693,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31778,"lbm_writes_lt_1ms":543,"mutex_wait_us":399,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:19:42.658035 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:42.702509 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.044s	user 0.042s	sys 0.000s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19390,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.703053 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:42.856118 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.153s	user 0.100s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":253,"lbm_read_time_us":9734,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25119,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2000}
I20260812 06:19:42.856973 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:42.908177 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.051s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20982,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.908840 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:42.921320 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.922019 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:43.115638 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.193s	user 0.124s	sys 0.063s 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":263,"lbm_read_time_us":12360,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31216,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:19:43.116362 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=11.118625
I20260812 06:19:43.145659 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.029s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12697,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.146389 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:43.168289 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.021s	user 0.004s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7104,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.169018 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:43.308543 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.139s	user 0.113s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":589,"lbm_read_time_us":9524,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27278,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:19:43.309391 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=11.118625
I20260812 06:19:43.342127 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.032s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14325,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.342692 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:43.354871 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4574,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.355378 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:43.486441 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.131s	user 0.091s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1093,"lbm_read_time_us":10394,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23004,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:19:43.487077 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=10.126437
I20260812 06:19:43.535382 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.048s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.535878 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:43.547433 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.548393 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushMRSOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:43.583182 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushMRSOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1763,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1497,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:43.583789 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling LogGCOp(04467b9743d14ac1a6add337aaa499b4): free 128867439 bytes of WAL
I20260812 06:19:43.584018 20474 log_reader.cc:385] T 04467b9743d14ac1a6add337aaa499b4: removed 13 log segments from log reader
I20260812 06:19:43.584081 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000003 (ops 12-16)
I20260812 06:19:43.584134 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000004 (ops 17-20)
I20260812 06:19:43.584190 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000005 (ops 21-25)
I20260812 06:19:43.584232 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000006 (ops 26-30)
I20260812 06:19:43.584287 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000007 (ops 31-35)
I20260812 06:19:43.584327 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000008 (ops 36-40)
I20260812 06:19:43.584362 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000009 (ops 41-44)
I20260812 06:19:43.584399 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000010 (ops 45-49)
I20260812 06:19:43.584435 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000011 (ops 50-54)
I20260812 06:19:43.584472 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000012 (ops 55-59)
I20260812 06:19:43.584508 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000013 (ops 60-64)
I20260812 06:19:43.584554 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000014 (ops 65-68)
I20260812 06:19:43.584589 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000015 (ops 69-73)
I20260812 06:19:43.616858 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: LogGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.033s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:19:43.617533 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=3.181125
I20260812 06:19:43.631666 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.014s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4923143,"delete_count":0,"lbm_write_time_us":5517,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 06:19:43.632180 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:43.645881 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":4594,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:43.646514 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:43.819398 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.173s	user 0.115s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877319,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2016,"lbm_read_time_us":12014,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35912,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:43.820225 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4): 481 bytes on disk
I20260812 06:19:43.820834 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.821430 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:43.878590 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.057s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23076,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.879165 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:43.892712 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.893456 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:44.064751 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.171s	user 0.119s	sys 0.048s 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":401,"lbm_read_time_us":12047,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32681,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:19:44.065510 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=11.118625
I20260812 06:19:44.102738 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16420,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.103304 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:44.122148 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.019s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5691,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.122599 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:44.272101 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.149s	user 0.116s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":10260,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25175,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.272740 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:44.336947 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.064s	user 0.025s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22286,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.337555 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:44.353497 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.353976 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:44.539932 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.186s	user 0.122s	sys 0.060s 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":248,"lbm_read_time_us":12510,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31514,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:44.540509 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=11.118625
I20260812 06:19:44.586814 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.046s	user 0.035s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19573,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.587575 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:44.602329 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5156,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.602828 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:44.736629 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.134s	user 0.125s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":714,"lbm_read_time_us":8857,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26786,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:19:44.737216 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=10.126437
I20260812 06:19:44.776010 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.039s	user 0.031s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16307,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.776476 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:44.787922 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.788424 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:44.932984 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.144s	user 0.105s	sys 0.039s 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":156,"lbm_read_time_us":9110,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26562,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:44.933588 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=10.126437
I20260812 06:19:44.986102 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.052s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17822,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.986593 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:44.998000 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.998839 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushMRSOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:45.029932 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushMRSOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1387,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1623,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:45.030731 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling LogGCOp(04467b9743d14ac1a6add337aaa499b4): free 112239271 bytes of WAL
I20260812 06:19:45.031026 20474 log_reader.cc:385] T 04467b9743d14ac1a6add337aaa499b4: removed 11 log segments from log reader
I20260812 06:19:45.031097 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000016 (ops 74-78)
I20260812 06:19:45.031148 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000017 (ops 79-83)
I20260812 06:19:45.031208 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000018 (ops 84-88)
I20260812 06:19:45.031250 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000019 (ops 89-92)
I20260812 06:19:45.031286 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000020 (ops 93-97)
I20260812 06:19:45.031327 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000021 (ops 98-102)
I20260812 06:19:45.031366 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000022 (ops 103-107)
I20260812 06:19:45.031406 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000023 (ops 108-112)
I20260812 06:19:45.031445 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000024 (ops 113-117)
I20260812 06:19:45.031486 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000025 (ops 118-122)
I20260812 06:19:45.031524 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000026 (ops 123-127)
I20260812 06:19:45.057559 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: LogGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:45.058063 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4): 448 bytes on disk
I20260812 06:19:45.058614 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.059305 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=3.181125
I20260812 06:19:45.077725 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4882122,"delete_count":0,"lbm_write_time_us":7721,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:19:45.078194 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:45.088025 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3340,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:19:45.088624 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:45.270596 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.182s	user 0.145s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":885,"lbm_read_time_us":14176,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37951,"lbm_writes_lt_1ms":643,"mutex_wait_us":354,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:45.271334 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:45.329084 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.058s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20014,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.329596 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:45.347673 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.348325 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:45.509836 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.161s	user 0.080s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":924,"lbm_read_time_us":9489,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29614,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:19:45.510586 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:45.566614 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.056s	user 0.012s	sys 0.035s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.567128 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:45.720217 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.153s	user 0.079s	sys 0.065s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":373,"lbm_read_time_us":9598,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23290,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:45.720988 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:45.771785 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.051s	user 0.025s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20518,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.772396 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:45.787667 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.788384 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:45.984097 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.195s	user 0.132s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":394,"lbm_read_time_us":11858,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33674,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.984928 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:46.032594 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.047s	user 0.021s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18529,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.033147 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:46.045662 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.046402 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:46.202231 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.156s	user 0.101s	sys 0.047s 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":693,"lbm_read_time_us":10623,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30515,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:19:46.202828 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:46.253887 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.051s	user 0.032s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.254531 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:46.271071 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.271646 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:46.431977 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.160s	user 0.112s	sys 0.046s 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":982,"lbm_read_time_us":10846,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33879,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:19:46.432636 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=11.118625
I20260812 06:19:46.465256 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.032s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":13647,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.466009 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:46.479650 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5334,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.480135 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushMRSOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:46.531500 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushMRSOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.051s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1578,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1685,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:46.532429 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling LogGCOp(04467b9743d14ac1a6add337aaa499b4): free 120553692 bytes of WAL
I20260812 06:19:46.532686 20474 log_reader.cc:385] T 04467b9743d14ac1a6add337aaa499b4: removed 12 log segments from log reader
I20260812 06:19:46.532755 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000027 (ops 128-132)
I20260812 06:19:46.532835 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000028 (ops 133-136)
I20260812 06:19:46.532892 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000029 (ops 137-141)
I20260812 06:19:46.532941 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000030 (ops 142-146)
I20260812 06:19:46.532977 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000031 (ops 147-150)
I20260812 06:19:46.533015 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000032 (ops 151-155)
I20260812 06:19:46.533052 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000033 (ops 156-160)
I20260812 06:19:46.533088 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000034 (ops 161-165)
I20260812 06:19:46.533125 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000035 (ops 166-170)
I20260812 06:19:46.533162 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000036 (ops 171-175)
I20260812 06:19:46.533197 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000037 (ops 176-180)
I20260812 06:19:46.533234 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000038 (ops 181-185)
I20260812 06:19:46.562752 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: LogGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:46.563272 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=6.157687
I20260812 06:19:46.591316 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.028s	user 0.013s	sys 0.012s Metrics: {"bytes_written":8246104,"delete_count":0,"lbm_write_time_us":12242,"lbm_writes_lt_1ms":204,"reinsert_count":0,"update_count":1005}
I20260812 06:19:46.591843 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling LogGCOp(04467b9743d14ac1a6add337aaa499b4): free 8767143 bytes of WAL
I20260812 06:19:46.592065 20474 log_reader.cc:385] T 04467b9743d14ac1a6add337aaa499b4: removed 1 log segments from log reader
I20260812 06:19:46.592127 20474 log.cc:1079] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: Deleting log segment in path: /tmp/dist-test-taskLoHCyx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515575304583-19932-0/minicluster-data/ts-0-root/wals/04467b9743d14ac1a6add337aaa499b4/wal-000000039 (ops 186-190)
I20260812 06:19:46.594026 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: LogGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:46.594394 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=2.188937
I20260812 06:19:46.606810 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4061633,"delete_count":0,"lbm_write_time_us":4811,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:46.607306 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4): 482 bytes on disk
I20260812 06:19:46.607744 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: UndoDeltaBlockGCOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.608276 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:46.812103 19932 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.917s	user 1.815s	sys 0.152s
I20260812 06:19:46.840451 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.232s	user 0.137s	sys 0.091s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17231,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37622,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":3500}
I20260812 06:19:46.841046 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4): perf score=14.095187
I20260812 06:19:46.878659 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: FlushDeltaMemStoresOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.037s	user 0.019s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16176,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.879284 20595 maintenance_manager.cc:419] P 407b384e135d4a13865b9cef6cfa203b: Scheduling MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4): perf score=1.000000
I20260812 06:19:46.892696 19932 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.001s	sys 0.000s
I20260812 06:19:46.893366 19932 tablet_server.cc:179] TabletServer@127.19.119.1:0 shutting down...
I20260812 06:19:46.996129 20474 maintenance_manager.cc:643] P 407b384e135d4a13865b9cef6cfa203b: MajorDeltaCompactionOp(04467b9743d14ac1a6add337aaa499b4) complete. Timing: real 0.117s	user 0.080s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":354,"lbm_read_time_us":9243,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24190,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:19:46.996923 19932 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:46.997227 19932 tablet_replica.cc:333] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b: stopping tablet replica
I20260812 06:19:46.997360 19932 raft_consensus.cc:2243] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:46.997545 19932 raft_consensus.cc:2272] T 04467b9743d14ac1a6add337aaa499b4 P 407b384e135d4a13865b9cef6cfa203b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.013199 19932 tablet_server.cc:196] TabletServer@127.19.119.1:0 shutdown complete.
I20260812 06:19:47.035024 19932 master.cc:562] Master@127.19.119.62:35903 shutting down...
I20260812 06:19:47.039031 19932 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.039224 19932 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.039275 19932 tablet_replica.cc:333] T 00000000000000000000000000000000 P f9b30c7db5f244a7ad13509246df7787: stopping tablet replica
I20260812 06:19:47.051864 19932 master.cc:584] Master@127.19.119.62:35903 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5467 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11841 ms total)

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