[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:56.889636 24991 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.103.254:41689
I20260812 06:16:56.890770 24991 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:56.891425 24991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:56.898603 25002 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:16:56.898676 25001 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:16:56.898809 24991 server_base.cc:1061] running on GCE node
W20260812 06:16:56.899008 25005 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:56.899622 24991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:56.899739 24991 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:56.899811 24991 hybrid_clock.cc:648] HybridClock initialized: now 1786515416899809 us; error 0 us; skew 500 ppm
I20260812 06:16:56.901963 24991 webserver.cc:533] Webserver started at http://127.24.103.254:40049/ using document root <none> and password file <none>
I20260812 06:16:56.902699 24991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:56.902814 24991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:56.903134 24991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:56.904982 24991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/master-0-root/instance:
uuid: "4a78efb78b4b4b59bd956f8b52f8612e"
format_stamp: "Formatted at 2026-08-12 06:16:56 on dist-test-slave-7kzw"
I20260812 06:16:56.909060 24991 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.000s
I20260812 06:16:56.911767 25014 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:56.913028 24991 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:56.913189 24991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/master-0-root
uuid: "4a78efb78b4b4b59bd956f8b52f8612e"
format_stamp: "Formatted at 2026-08-12 06:16:56 on dist-test-slave-7kzw"
I20260812 06:16:56.913308 24991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:56.924975 24991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:56.925642 24991 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:56.925828 24991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:56.933785 25101 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.254:41689 every 8 connection(s)
I20260812 06:16:56.933784 24991 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.254:41689
I20260812 06:16:56.936342 25103 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:56.941767 25103 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e: Bootstrap starting.
I20260812 06:16:56.944244 25103 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:56.945165 25103 log.cc:826] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:56.947224 25103 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e: No bootstrap required, opened a new log
I20260812 06:16:56.950160 25103 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a78efb78b4b4b59bd956f8b52f8612e" member_type: VOTER }
I20260812 06:16:56.950352 25103 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:56.950397 25103 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4a78efb78b4b4b59bd956f8b52f8612e, State: Initialized, Role: FOLLOWER
I20260812 06:16:56.951170 25103 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [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: "4a78efb78b4b4b59bd956f8b52f8612e" member_type: VOTER }
I20260812 06:16:56.951346 25103 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:56.951437 25103 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:56.951608 25103 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:56.952488 25103 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a78efb78b4b4b59bd956f8b52f8612e" member_type: VOTER }
I20260812 06:16:56.952975 25103 leader_election.cc:304] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [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: 4a78efb78b4b4b59bd956f8b52f8612e; no voters: 
I20260812 06:16:56.953341 25103 leader_election.cc:290] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:56.953558 25108 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:56.953882 25108 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 1 LEADER]: Becoming Leader. State: Replica: 4a78efb78b4b4b59bd956f8b52f8612e, State: Running, Role: LEADER
I20260812 06:16:56.954278 25108 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [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: "4a78efb78b4b4b59bd956f8b52f8612e" member_type: VOTER }
I20260812 06:16:56.954527 25103 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:56.956504 25110 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4a78efb78b4b4b59bd956f8b52f8612e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a78efb78b4b4b59bd956f8b52f8612e" member_type: VOTER } }
I20260812 06:16:56.956542 25111 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4a78efb78b4b4b59bd956f8b52f8612e. Latest consensus state: current_term: 1 leader_uuid: "4a78efb78b4b4b59bd956f8b52f8612e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a78efb78b4b4b59bd956f8b52f8612e" member_type: VOTER } }
I20260812 06:16:56.956645 25110 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:56.956645 25111 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:56.957027 24991 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:56.957023 25130 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:56.959822 25130 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:56.965322 25130 catalog_manager.cc:1383] Generated new cluster ID: 8b342f8e1d2444579b98f81cff91c924
I20260812 06:16:56.965446 25130 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:56.980751 25130 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:56.981743 25130 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:56.987475 25130 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e: Generated new TSK 0
I20260812 06:16:56.988164 25130 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:56.989836 24991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:56.993152 25139 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:56.993183 25141 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:56.993310 24991 server_base.cc:1061] running on GCE node
W20260812 06:16:56.993180 25146 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:56.993839 24991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:56.993891 24991 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:56.993908 24991 hybrid_clock.cc:648] HybridClock initialized: now 1786515416993909 us; error 0 us; skew 500 ppm
I20260812 06:16:56.995056 24991 webserver.cc:533] Webserver started at http://127.24.103.193:46123/ using document root <none> and password file <none>
I20260812 06:16:56.995265 24991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:56.995354 24991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:56.995447 24991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:56.995918 24991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/instance:
uuid: "8fe12f41ba1142baa27c2890fa120833"
format_stamp: "Formatted at 2026-08-12 06:16:56 on dist-test-slave-7kzw"
I20260812 06:16:56.997675 24991 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:56.998895 25153 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:56.999208 24991 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:56.999282 24991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root
uuid: "8fe12f41ba1142baa27c2890fa120833"
format_stamp: "Formatted at 2026-08-12 06:16:56 on dist-test-slave-7kzw"
I20260812 06:16:56.999379 24991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:57.016762 24991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:57.017835 24991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:57.018502 24991 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:57.019786 24991 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:57.019878 24991 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:57.019984 24991 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:57.020027 24991 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:57.028209 24991 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.193:46163
I20260812 06:16:57.028267 25258 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.193:46163 every 8 connection(s)
I20260812 06:16:57.040948 25261 heartbeater.cc:344] Connected to a master server at 127.24.103.254:41689
I20260812 06:16:57.041303 25261 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:57.041908 25261 heartbeater.cc:507] Master 127.24.103.254:41689 requested a full tablet report, sending...
I20260812 06:16:57.043728 25047 ts_manager.cc:194] Registered new tserver with Master: 8fe12f41ba1142baa27c2890fa120833 (127.24.103.193:46163)
I20260812 06:16:57.044226 24991 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015027762s
I20260812 06:16:57.045413 25047 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43110
I20260812 06:16:57.054870 25047 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43118:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:57.070353 25201 tablet_service.cc:1511] Processing CreateTablet for tablet e24f59280f714f8d8bce990245159d34 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b5bf1cff588c49ffb01096a0844ab6bb]), partition=
I20260812 06:16:57.070971 25201 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e24f59280f714f8d8bce990245159d34. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:57.073175 25281 tablet_bootstrap.cc:492] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Bootstrap starting.
I20260812 06:16:57.074417 25281 tablet_bootstrap.cc:654] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:57.075614 25281 tablet_bootstrap.cc:492] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: No bootstrap required, opened a new log
I20260812 06:16:57.075727 25281 ts_tablet_manager.cc:1403] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:57.076189 25281 raft_consensus.cc:359] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fe12f41ba1142baa27c2890fa120833" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 46163 } }
I20260812 06:16:57.076299 25281 raft_consensus.cc:385] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:57.076323 25281 raft_consensus.cc:740] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8fe12f41ba1142baa27c2890fa120833, State: Initialized, Role: FOLLOWER
I20260812 06:16:57.076521 25281 consensus_queue.cc:260] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [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: "8fe12f41ba1142baa27c2890fa120833" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 46163 } }
I20260812 06:16:57.076606 25281 raft_consensus.cc:399] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:57.076668 25281 raft_consensus.cc:493] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:57.076720 25281 raft_consensus.cc:3060] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:57.077536 25281 raft_consensus.cc:515] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fe12f41ba1142baa27c2890fa120833" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 46163 } }
I20260812 06:16:57.077711 25281 leader_election.cc:304] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [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: 8fe12f41ba1142baa27c2890fa120833; no voters: 
I20260812 06:16:57.077973 25281 leader_election.cc:290] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:57.078073 25285 raft_consensus.cc:2804] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:57.078344 25285 raft_consensus.cc:697] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 1 LEADER]: Becoming Leader. State: Replica: 8fe12f41ba1142baa27c2890fa120833, State: Running, Role: LEADER
I20260812 06:16:57.078382 25281 ts_tablet_manager.cc:1434] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:57.078608 25285 consensus_queue.cc:237] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [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: "8fe12f41ba1142baa27c2890fa120833" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 46163 } }
I20260812 06:16:57.078853 25261 heartbeater.cc:499] Master 127.24.103.254:41689 was elected leader, sending a full tablet report...
I20260812 06:16:57.081914 25047 catalog_manager.cc:5719] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8fe12f41ba1142baa27c2890fa120833 (127.24.103.193). New cstate: current_term: 1 leader_uuid: "8fe12f41ba1142baa27c2890fa120833" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fe12f41ba1142baa27c2890fa120833" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 46163 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:57.150782 24991 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.009s	sys 0.020s
I20260812 06:16:57.279662 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushMRSOp(e24f59280f714f8d8bce990245159d34): perf score=15.086190
I20260812 06:16:57.433202 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushMRSOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.153s	user 0.117s	sys 0.023s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":225,"delete_count":0,"dirs.queue_time_us":30,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":827,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35802,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":93,"threads_started":1,"update_count":1450}
I20260812 06:16:57.434240 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling LogGCOp(e24f59280f714f8d8bce990245159d34): free 20743880 bytes of WAL
I20260812 06:16:57.434614 25162 log_reader.cc:385] T e24f59280f714f8d8bce990245159d34: removed 2 log segments from log reader
I20260812 06:16:57.434695 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000001 (ops 1-6)
I20260812 06:16:57.434775 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000002 (ops 7-11)
I20260812 06:16:57.439118 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: LogGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:16:57.439446 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34): 12719216 bytes on disk
I20260812 06:16:57.440001 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.440387 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:57.460948 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.461444 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:57.601150 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.139s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":7761,"lbm_reads_lt_1ms":450,"lbm_write_time_us":27129,"lbm_writes_lt_1ms":433,"mutex_wait_us":38,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":334,"threads_started":5,"update_count":1950}
I20260812 06:16:57.601681 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:57.647864 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.046s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17413,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.648352 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:57.658704 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.659134 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:57.789795 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.130s	user 0.097s	sys 0.024s 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":233,"lbm_read_time_us":9189,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23548,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:57.790410 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:57.837389 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.047s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18003,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:57.837875 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:57.849184 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.849817 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:57.975401 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.125s	user 0.113s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":426,"lbm_read_time_us":9443,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23398,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:57.976693 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:58.023842 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.047s	user 0.024s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.024387 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.035480 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.035992 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:58.186228 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.150s	user 0.096s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1493,"lbm_read_time_us":10270,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24591,"lbm_writes_lt_1ms":443,"mutex_wait_us":433,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:16:58.189298 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:58.230031 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.040s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18479,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.230556 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.249495 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.250082 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:58.378685 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.128s	user 0.099s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":947,"lbm_read_time_us":8972,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25937,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":2000}
I20260812 06:16:58.379313 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:58.415303 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15497,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.415827 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.426975 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.427582 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:58.563175 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.135s	user 0.101s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1113,"lbm_read_time_us":9454,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25333,"lbm_writes_lt_1ms":443,"mutex_wait_us":494,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:16:58.563992 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:58.608450 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.044s	user 0.024s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17889,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.608942 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.619541 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.620026 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:58.753759 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.134s	user 0.098s	sys 0.032s 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":685,"lbm_read_time_us":8093,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28734,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:16:58.754554 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:16:58.809922 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.055s	user 0.024s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18473,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.810608 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.821468 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.822084 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushMRSOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:58.863418 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushMRSOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.041s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1416,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1399,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:58.864503 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling LogGCOp(e24f59280f714f8d8bce990245159d34): free 124710247 bytes of WAL
I20260812 06:16:58.864809 25162 log_reader.cc:385] T e24f59280f714f8d8bce990245159d34: removed 12 log segments from log reader
I20260812 06:16:58.864888 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000003 (ops 12-16)
I20260812 06:16:58.864944 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000004 (ops 17-21)
I20260812 06:16:58.865002 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000005 (ops 22-26)
I20260812 06:16:58.865046 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000006 (ops 27-31)
I20260812 06:16:58.865085 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000007 (ops 32-36)
I20260812 06:16:58.865139 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000008 (ops 37-41)
I20260812 06:16:58.865176 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000009 (ops 42-46)
I20260812 06:16:58.865214 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000010 (ops 47-51)
I20260812 06:16:58.865252 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000011 (ops 52-56)
I20260812 06:16:58.865288 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000012 (ops 57-61)
I20260812 06:16:58.865324 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000013 (ops 62-66)
I20260812 06:16:58.865361 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000014 (ops 67-71)
I20260812 06:16:58.894717 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: LogGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:58.895174 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34): 482 bytes on disk
I20260812 06:16:58.895660 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.896220 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.916709 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.020s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.917219 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:58.928342 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.928819 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:59.130798 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.202s	user 0.124s	sys 0.074s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":221,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35041,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":62976,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:16:59.132071 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:16:59.184281 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.052s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22419,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.184864 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:59.339562 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.154s	user 0.103s	sys 0.040s 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":363,"lbm_read_time_us":10046,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22854,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:59.340133 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:16:59.392750 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.052s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22932,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.393354 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:59.409684 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.410274 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:59.600724 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.190s	user 0.130s	sys 0.049s 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":228,"lbm_read_time_us":11638,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29142,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:16:59.601424 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:16:59.657888 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.056s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21897,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.658526 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:59.674019 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.674742 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:16:59.827239 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.152s	user 0.118s	sys 0.032s 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":523,"lbm_read_time_us":10047,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29901,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:59.827984 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=11.118625
I20260812 06:16:59.865214 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.037s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15776,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:59.865876 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:59.891917 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5079,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.892436 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:16:59.903457 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.903959 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:00.063462 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.159s	user 0.126s	sys 0.026s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":176,"lbm_read_time_us":11277,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29786,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2500}
I20260812 06:17:00.064222 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:17:00.121475 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.057s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23790,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.122114 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:00.136786 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.137409 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:00.287093 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.149s	user 0.117s	sys 0.032s 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":688,"lbm_read_time_us":10601,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28483,"lbm_writes_lt_1ms":543,"mutex_wait_us":490,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:17:00.287882 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=11.118625
I20260812 06:17:00.326198 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.038s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16999,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:00.326902 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:00.341552 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5246,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.342177 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushMRSOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:00.376824 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushMRSOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.034s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1393,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1598,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:00.377658 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling LogGCOp(e24f59280f714f8d8bce990245159d34): free 124257305 bytes of WAL
I20260812 06:17:00.377907 25162 log_reader.cc:385] T e24f59280f714f8d8bce990245159d34: removed 12 log segments from log reader
I20260812 06:17:00.377955 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000015 (ops 72-76)
I20260812 06:17:00.377985 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000016 (ops 77-81)
I20260812 06:17:00.378047 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000017 (ops 82-86)
I20260812 06:17:00.378103 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000018 (ops 87-90)
I20260812 06:17:00.378149 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000019 (ops 91-95)
I20260812 06:17:00.378189 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000020 (ops 96-100)
I20260812 06:17:00.378229 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000021 (ops 101-105)
I20260812 06:17:00.378269 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000022 (ops 106-110)
I20260812 06:17:00.378309 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000023 (ops 111-115)
I20260812 06:17:00.378347 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000024 (ops 116-120)
I20260812 06:17:00.378386 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000025 (ops 121-125)
I20260812 06:17:00.378428 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000026 (ops 126-130)
I20260812 06:17:00.407151 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: LogGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:00.407569 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34): 473 bytes on disk
I20260812 06:17:00.408183 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.408788 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=4.173312
I20260812 06:17:00.423092 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":5620561,"delete_count":0,"lbm_write_time_us":5688,"lbm_writes_lt_1ms":140,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":685}
I20260812 06:17:00.423558 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=1.196750
I20260812 06:17:00.432900 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":2667,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:17:00.433454 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:00.611809 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.178s	user 0.146s	sys 0.031s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877297,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":799,"lbm_read_time_us":13195,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37061,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:00.612607 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:17:00.670724 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.058s	user 0.050s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25688,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:00.671247 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:00.685029 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.685513 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:00.837554 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.152s	user 0.111s	sys 0.040s 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":307,"lbm_read_time_us":10185,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30706,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:17:00.838428 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=11.118625
I20260812 06:17:00.886057 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.047s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12881835,"delete_count":0,"lbm_write_time_us":22093,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":316,"reinsert_count":0,"update_count":1570}
I20260812 06:17:00.886621 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:00.908298 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.021s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:17:00.908821 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:00.919711 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.920424 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:01.109604 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.189s	user 0.130s	sys 0.052s 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":348,"lbm_read_time_us":14264,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32888,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:17:01.110133 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:17:01.169997 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.060s	user 0.018s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22922,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.170611 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:01.181821 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.182365 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:01.356520 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.174s	user 0.108s	sys 0.061s 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":150,"lbm_read_time_us":12172,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31321,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:01.357229 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=14.095187
I20260812 06:17:01.417212 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.060s	user 0.018s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22173,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.417919 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:01.434883 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.017s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.435458 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:01.617359 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.182s	user 0.100s	sys 0.079s 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":538,"lbm_read_time_us":13693,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30763,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:01.618507 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=11.118625
I20260812 06:17:01.661362 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.043s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19166,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.662031 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:01.687341 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.025s	user 0.017s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5727,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.687820 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:01.842371 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.154s	user 0.105s	sys 0.047s 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":4739,"lbm_read_time_us":10172,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25180,"lbm_writes_lt_1ms":443,"mutex_wait_us":2332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:17:01.843142 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:17:01.890220 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.047s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17669,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.890861 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=2.188937
I20260812 06:17:01.904646 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4595,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.905339 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushMRSOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:01.937399 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushMRSOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1493,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1615,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:01.938071 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling LogGCOp(e24f59280f714f8d8bce990245159d34): free 124710577 bytes of WAL
I20260812 06:17:01.938313 25162 log_reader.cc:385] T e24f59280f714f8d8bce990245159d34: removed 12 log segments from log reader
I20260812 06:17:01.938434 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000027 (ops 131-135)
I20260812 06:17:01.938598 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000028 (ops 136-140)
I20260812 06:17:01.938669 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000029 (ops 141-145)
I20260812 06:17:01.938741 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000030 (ops 146-150)
I20260812 06:17:01.938792 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000031 (ops 151-155)
I20260812 06:17:01.938838 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000032 (ops 156-160)
I20260812 06:17:01.938882 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000033 (ops 161-165)
I20260812 06:17:01.938926 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000034 (ops 166-170)
I20260812 06:17:01.938970 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000035 (ops 171-175)
I20260812 06:17:01.939014 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000036 (ops 176-180)
I20260812 06:17:01.939059 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000037 (ops 181-185)
I20260812 06:17:01.939102 25162 log.cc:1079] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/e24f59280f714f8d8bce990245159d34/wal-000000038 (ops 186-190)
I20260812 06:17:01.973146 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: LogGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.035s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:01.973733 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=4.173312
I20260812 06:17:01.993201 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.019s	user 0.012s	sys 0.005s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":7627,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:17:01.993825 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34): 472 bytes on disk
I20260812 06:17:01.994377 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: UndoDeltaBlockGCOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:01.995023 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=1.196750
I20260812 06:17:02.009234 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4884,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:02.009733 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34): perf score=1.000000
I20260812 06:17:02.144492 24991 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.994s	user 1.890s	sys 0.106s
I20260812 06:17:02.193936 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: MajorDeltaCompactionOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.184s	user 0.134s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":11101,"lbm_reads_lt_1ms":666,"lbm_write_time_us":34525,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:02.194568 25262 maintenance_manager.cc:419] P 8fe12f41ba1142baa27c2890fa120833: Scheduling FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34): perf score=10.126437
I20260812 06:17:02.222038 24991 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.003s	sys 0.000s
I20260812 06:17:02.222963 24991 tablet_server.cc:179] TabletServer@127.24.103.193:0 shutting down...
I20260812 06:17:02.236387 25162 maintenance_manager.cc:643] P 8fe12f41ba1142baa27c2890fa120833: FlushDeltaMemStoresOp(e24f59280f714f8d8bce990245159d34) complete. Timing: real 0.042s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17739,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.237008 24991 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:02.237475 24991 tablet_replica.cc:333] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833: stopping tablet replica
I20260812 06:17:02.237726 24991 raft_consensus.cc:2243] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:02.237931 24991 raft_consensus.cc:2272] T e24f59280f714f8d8bce990245159d34 P 8fe12f41ba1142baa27c2890fa120833 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:02.253968 24991 tablet_server.cc:196] TabletServer@127.24.103.193:0 shutdown complete.
I20260812 06:17:02.259351 24991 master.cc:562] Master@127.24.103.254:41689 shutting down...
I20260812 06:17:02.263414 24991 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:02.263614 24991 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:02.263703 24991 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4a78efb78b4b4b59bd956f8b52f8612e: stopping tablet replica
I20260812 06:17:02.276232 24991 master.cc:584] Master@127.24.103.254:41689 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5480 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:02.381748 24991 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.103.254:40139
I20260812 06:17:02.382200 24991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:02.384618 24991 server_base.cc:1061] running on GCE node
W20260812 06:17:02.384564 25320 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.384558 25321 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:17:02.384558 25323 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.385048 24991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.385098 24991 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:02.385119 24991 hybrid_clock.cc:648] HybridClock initialized: now 1786515422385119 us; error 0 us; skew 500 ppm
I20260812 06:17:02.386029 24991 webserver.cc:533] Webserver started at http://127.24.103.254:34415/ using document root <none> and password file <none>
I20260812 06:17:02.386178 24991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.386225 24991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.386287 24991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.386775 24991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/master-0-root/instance:
uuid: "93ecffd6149b4e9695adc7037fa9d2bd"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-7kzw"
I20260812 06:17:02.388357 24991 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:02.389449 25330 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.389719 24991 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:02.389822 24991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/master-0-root
uuid: "93ecffd6149b4e9695adc7037fa9d2bd"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-7kzw"
I20260812 06:17:02.389915 24991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:02.418813 24991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.419265 24991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.424235 24991 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.254:40139
I20260812 06:17:02.426983 25411 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.430658 25409 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.254:40139 every 8 connection(s)
I20260812 06:17:02.431900 25411 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd: Bootstrap starting.
I20260812 06:17:02.432701 25411 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.433736 25411 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd: No bootstrap required, opened a new log
I20260812 06:17:02.434155 25411 raft_consensus.cc:359] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER }
I20260812 06:17:02.434267 25411 raft_consensus.cc:385] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.434319 25411 raft_consensus.cc:740] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 93ecffd6149b4e9695adc7037fa9d2bd, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.434590 25411 consensus_queue.cc:260] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [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: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER }
I20260812 06:17:02.434734 25417 raft_consensus.cc:493] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Starting pre-election (no leader contacted us within the election timeout)
I20260812 06:17:02.434849 25417 raft_consensus.cc:515] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Starting pre-election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER }
I20260812 06:17:02.435061 25417 leader_election.cc:304] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [CANDIDATE]: Term 1 pre-election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 93ecffd6149b4e9695adc7037fa9d2bd; no voters: 
I20260812 06:17:02.435094 25411 raft_consensus.cc:399] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.435166 25411 raft_consensus.cc:493] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.435227 25411 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.435300 25417 leader_election.cc:290] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [CANDIDATE]: Term 1 pre-election: Requested pre-vote from peers 
I20260812 06:17:02.435979 25411 raft_consensus.cc:515] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER }
I20260812 06:17:02.436143 25411 leader_election.cc:304] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [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: 93ecffd6149b4e9695adc7037fa9d2bd; no voters: 
I20260812 06:17:02.436208 25418 raft_consensus.cc:2764] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 1 FOLLOWER]: Leader pre-election decision vote started in defunct term 0: won
I20260812 06:17:02.436264 25411 leader_election.cc:290] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.436367 25417 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.436460 25417 raft_consensus.cc:697] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 1 LEADER]: Becoming Leader. State: Replica: 93ecffd6149b4e9695adc7037fa9d2bd, State: Running, Role: LEADER
I20260812 06:17:02.436591 25417 consensus_queue.cc:237] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [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: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER }
I20260812 06:17:02.436766 25411 sys_catalog.cc:565] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:02.437003 25418 sys_catalog.cc:455] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER } }
I20260812 06:17:02.437021 25417 sys_catalog.cc:455] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 93ecffd6149b4e9695adc7037fa9d2bd. Latest consensus state: current_term: 1 leader_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93ecffd6149b4e9695adc7037fa9d2bd" member_type: VOTER } }
I20260812 06:17:02.437166 25418 sys_catalog.cc:458] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.437248 25417 sys_catalog.cc:458] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.437767 25423 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:02.438827 25423 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:02.439045 24991 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:02.440735 25423 catalog_manager.cc:1383] Generated new cluster ID: 89d954ac12d94db3a309bf2d8f0005e0
I20260812 06:17:02.440794 25423 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:02.448408 25423 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:02.448954 25423 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:02.456720 25423 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd: Generated new TSK 0
I20260812 06:17:02.456909 25423 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:02.471671 24991 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:02.474042 24991 server_base.cc:1061] running on GCE node
W20260812 06:17:02.474071 25451 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.474117 25447 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.474117 25448 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.474535 24991 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.474617 24991 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:02.474659 24991 hybrid_clock.cc:648] HybridClock initialized: now 1786515422474659 us; error 0 us; skew 500 ppm
I20260812 06:17:02.475633 24991 webserver.cc:533] Webserver started at http://127.24.103.193:45057/ using document root <none> and password file <none>
I20260812 06:17:02.475818 24991 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.475879 24991 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.475982 24991 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.476430 24991 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/instance:
uuid: "ca67f3c062e14fec881747622365a832"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-7kzw"
I20260812 06:17:02.478024 24991 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:02.479094 25457 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.479362 24991 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:02.479457 24991 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root
uuid: "ca67f3c062e14fec881747622365a832"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-7kzw"
I20260812 06:17:02.479544 24991 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:02.501338 24991 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.501761 24991 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.502099 24991 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:02.502614 24991 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:02.502729 24991 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.502799 24991 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:02.502849 24991 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.507464 24991 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.193:38095
I20260812 06:17:02.507540 25553 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.193:38095 every 8 connection(s)
I20260812 06:17:02.518141 25554 heartbeater.cc:344] Connected to a master server at 127.24.103.254:40139
I20260812 06:17:02.518270 25554 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:02.518532 25554 heartbeater.cc:507] Master 127.24.103.254:40139 requested a full tablet report, sending...
I20260812 06:17:02.519193 25356 ts_manager.cc:194] Registered new tserver with Master: ca67f3c062e14fec881747622365a832 (127.24.103.193:38095)
I20260812 06:17:02.519287 24991 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011309424s
I20260812 06:17:02.520038 25356 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58330
I20260812 06:17:02.527140 25356 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58338:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:02.537145 25498 tablet_service.cc:1511] Processing CreateTablet for tablet 05d204862512494784bca3914c5a6f02 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2519662000ca49ab8a0b4c120242afd3]), partition=
I20260812 06:17:02.537456 25498 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 05d204862512494784bca3914c5a6f02. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.539872 25570 tablet_bootstrap.cc:492] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Bootstrap starting.
I20260812 06:17:02.540742 25570 tablet_bootstrap.cc:654] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.541976 25570 tablet_bootstrap.cc:492] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: No bootstrap required, opened a new log
I20260812 06:17:02.542084 25570 ts_tablet_manager.cc:1403] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:02.542729 25570 raft_consensus.cc:359] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca67f3c062e14fec881747622365a832" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 38095 } }
I20260812 06:17:02.542872 25570 raft_consensus.cc:385] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.542917 25570 raft_consensus.cc:740] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ca67f3c062e14fec881747622365a832, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.543128 25570 consensus_queue.cc:260] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [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: "ca67f3c062e14fec881747622365a832" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 38095 } }
I20260812 06:17:02.543207 25570 raft_consensus.cc:399] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.543232 25570 raft_consensus.cc:493] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.543284 25570 raft_consensus.cc:3060] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.544090 25570 raft_consensus.cc:515] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca67f3c062e14fec881747622365a832" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 38095 } }
I20260812 06:17:02.544226 25570 leader_election.cc:304] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [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: ca67f3c062e14fec881747622365a832; no voters: 
I20260812 06:17:02.544498 25570 leader_election.cc:290] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.544697 25573 raft_consensus.cc:2804] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.544844 25570 ts_tablet_manager.cc:1434] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:02.545037 25554 heartbeater.cc:499] Master 127.24.103.254:40139 was elected leader, sending a full tablet report...
I20260812 06:17:02.544996 25573 raft_consensus.cc:697] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 1 LEADER]: Becoming Leader. State: Replica: ca67f3c062e14fec881747622365a832, State: Running, Role: LEADER
I20260812 06:17:02.545233 25573 consensus_queue.cc:237] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [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: "ca67f3c062e14fec881747622365a832" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 38095 } }
I20260812 06:17:02.546730 25356 catalog_manager.cc:5719] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 reported cstate change: term changed from 0 to 1, leader changed from <none> to ca67f3c062e14fec881747622365a832 (127.24.103.193). New cstate: current_term: 1 leader_uuid: "ca67f3c062e14fec881747622365a832" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca67f3c062e14fec881747622365a832" member_type: VOTER last_known_addr { host: "127.24.103.193" port: 38095 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:02.607800 24991 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.004s	sys 0.018s
I20260812 06:17:02.758630 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushMRSOp(05d204862512494784bca3914c5a6f02): perf score=19.054940
I20260812 06:17:02.919018 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushMRSOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.160s	user 0.104s	sys 0.056s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":917,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39200,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:02.919847 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling LogGCOp(05d204862512494784bca3914c5a6f02): free 20743880 bytes of WAL
I20260812 06:17:02.920210 25463 log_reader.cc:385] T 05d204862512494784bca3914c5a6f02: removed 2 log segments from log reader
I20260812 06:17:02.920257 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000001 (ops 1-6)
I20260812 06:17:02.920291 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000002 (ops 7-11)
I20260812 06:17:02.924664 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: LogGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:02.925314 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02): 16411392 bytes on disk
I20260812 06:17:02.925838 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.926297 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:02.941229 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.941749 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:03.101042 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.159s	user 0.107s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":613,"lbm_read_time_us":11582,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23330,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":347,"threads_started":5,"update_count":2000}
I20260812 06:17:03.101672 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=11.118625
I20260812 06:17:03.139405 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.037s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16515,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:03.140031 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:03.157745 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5163,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.158228 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:03.282430 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.124s	user 0.092s	sys 0.032s 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":505,"lbm_read_time_us":8563,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22118,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:03.283170 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:03.328688 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.045s	user 0.032s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18938,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.329264 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:03.345139 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.345605 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:03.484411 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.139s	user 0.107s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":9107,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25532,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:17:03.485176 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:03.528359 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.043s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19583,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.528869 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:03.539331 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.539784 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:03.691478 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.152s	user 0.105s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":8994,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32858,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:03.692173 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:03.752367 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.060s	user 0.019s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16395,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.752978 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:03.769356 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.769956 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:03.925886 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.156s	user 0.100s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":372,"lbm_read_time_us":12331,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25674,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:03.926608 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:03.973129 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.046s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15651,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.973681 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:03.984439 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.985112 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:04.113583 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.128s	user 0.091s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":10211,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22713,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:17:04.114388 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:04.151182 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.037s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15826,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.151728 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:04.167894 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.168423 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushMRSOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:04.195909 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushMRSOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.027s	user 0.020s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1852,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1628,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":768}
I20260812 06:17:04.196668 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling LogGCOp(05d204862512494784bca3914c5a6f02): free 112692367 bytes of WAL
I20260812 06:17:04.196918 25463 log_reader.cc:385] T 05d204862512494784bca3914c5a6f02: removed 11 log segments from log reader
I20260812 06:17:04.196967 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000003 (ops 12-16)
I20260812 06:17:04.197022 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000004 (ops 17-21)
I20260812 06:17:04.197074 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000005 (ops 22-26)
I20260812 06:17:04.197120 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000006 (ops 27-31)
I20260812 06:17:04.197173 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000007 (ops 32-36)
I20260812 06:17:04.197240 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000008 (ops 37-41)
I20260812 06:17:04.197284 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000009 (ops 42-46)
I20260812 06:17:04.197328 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000010 (ops 47-51)
I20260812 06:17:04.197372 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000011 (ops 52-56)
I20260812 06:17:04.197420 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000012 (ops 57-61)
I20260812 06:17:04.197464 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000013 (ops 62-66)
I20260812 06:17:04.226590 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: LogGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:04.227085 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=3.181125
I20260812 06:17:04.239889 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.013s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.240363 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:04.251142 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4210,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.251780 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02): 447 bytes on disk
I20260812 06:17:04.252490 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.253198 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:04.441947 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.189s	user 0.121s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":199,"lbm_read_time_us":13290,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39971,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:17:04.442695 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:04.500473 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.058s	user 0.040s	sys 0.009s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":22590,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.500964 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:04.513489 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.514029 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:04.676566 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.162s	user 0.119s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":67,"lbm_read_time_us":10467,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34480,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:17:04.677148 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:04.710505 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.033s	user 0.010s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14218,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.711042 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:04.726037 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5526,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.726608 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:04.860939 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.134s	user 0.066s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1562,"lbm_read_time_us":9899,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22686,"lbm_writes_lt_1ms":443,"mutex_wait_us":468,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:17:04.861534 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:04.901001 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.039s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15219,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.901518 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:04.913542 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.914054 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:05.060953 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.147s	user 0.082s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":8830,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23366,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:17:05.061550 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:05.098847 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.037s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16388,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.099359 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:05.109709 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.110177 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:05.243072 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":10297,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25394,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:17:05.243782 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:05.280046 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15881,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.280658 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:05.386988 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.106s	user 0.078s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":272,"lbm_read_time_us":6487,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19799,"lbm_writes_lt_1ms":343,"mutex_wait_us":47,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":1500}
I20260812 06:17:05.387681 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:05.422423 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.035s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14610,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.422935 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:05.529268 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.106s	user 0.072s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569749,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":298,"lbm_read_time_us":6340,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19079,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":1500}
I20260812 06:17:05.529929 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=10.126437
I20260812 06:17:05.572506 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.042s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17355,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.573119 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushMRSOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:05.623438 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushMRSOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.050s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1616,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2162,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:05.624167 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling LogGCOp(05d204862512494784bca3914c5a6f02): free 115490125 bytes of WAL
I20260812 06:17:05.624395 25463 log_reader.cc:385] T 05d204862512494784bca3914c5a6f02: removed 11 log segments from log reader
I20260812 06:17:05.624459 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000014 (ops 67-71)
I20260812 06:17:05.624508 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000015 (ops 72-76)
I20260812 06:17:05.624547 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000016 (ops 77-81)
I20260812 06:17:05.624588 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000017 (ops 82-86)
I20260812 06:17:05.624629 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000018 (ops 87-91)
I20260812 06:17:05.624666 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000019 (ops 92-96)
I20260812 06:17:05.624704 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000020 (ops 97-101)
I20260812 06:17:05.624742 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000021 (ops 102-106)
I20260812 06:17:05.624780 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000022 (ops 107-111)
I20260812 06:17:05.624818 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000023 (ops 112-116)
I20260812 06:17:05.624856 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000024 (ops 117-120)
I20260812 06:17:05.651129 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: LogGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:05.651582 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02): 463 bytes on disk
I20260812 06:17:05.652014 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.652556 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=7.149875
I20260812 06:17:05.676290 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.024s	user 0.013s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10415,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:05.676798 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling LogGCOp(05d204862512494784bca3914c5a6f02): free 8767065 bytes of WAL
I20260812 06:17:05.677008 25463 log_reader.cc:385] T 05d204862512494784bca3914c5a6f02: removed 1 log segments from log reader
I20260812 06:17:05.677070 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000025 (ops 121-125)
I20260812 06:17:05.679003 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: LogGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:05.679363 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:05.692102 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4835,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.692544 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:05.861479 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.169s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877212,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":262,"lbm_read_time_us":13313,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32489,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28800,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:05.864840 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:05.918006 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.053s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22996,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.918814 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:05.936105 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.017s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.936668 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:06.100642 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.164s	user 0.112s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1367,"lbm_read_time_us":11432,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30233,"lbm_writes_lt_1ms":543,"mutex_wait_us":333,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:06.101366 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:06.167703 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.066s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":26756,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.168201 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:06.180572 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.181468 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:06.362608 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.181s	user 0.123s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":314,"lbm_read_time_us":13275,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32273,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:06.363128 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:06.416967 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.054s	user 0.033s	sys 0.018s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23304,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.417471 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:06.429010 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.429458 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:06.611340 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.182s	user 0.115s	sys 0.061s 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":458,"lbm_read_time_us":13783,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31546,"lbm_writes_lt_1ms":543,"mutex_wait_us":114,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29184,"update_count":2500}
I20260812 06:17:06.612047 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:06.673549 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.059s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20365,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.674177 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:06.685431 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.685948 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:06.872450 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.186s	user 0.120s	sys 0.055s 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":199,"lbm_read_time_us":12705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30986,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:17:06.873248 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:06.942921 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.069s	user 0.035s	sys 0.031s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25309,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.943455 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:06.954038 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.954667 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:07.151219 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.196s	user 0.115s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":13971,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32360,"lbm_writes_lt_1ms":543,"mutex_wait_us":88,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:07.151983 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:07.215176 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.063s	user 0.043s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.215667 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:07.239193 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.023s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":10527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.240027 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushMRSOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:07.289882 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushMRSOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.050s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1318,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1855,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:17:07.290668 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling LogGCOp(05d204862512494784bca3914c5a6f02): free 132571629 bytes of WAL
I20260812 06:17:07.290899 25463 log_reader.cc:385] T 05d204862512494784bca3914c5a6f02: removed 13 log segments from log reader
I20260812 06:17:07.290974 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000026 (ops 126-130)
I20260812 06:17:07.291030 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000027 (ops 131-135)
I20260812 06:17:07.291066 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000028 (ops 136-140)
I20260812 06:17:07.291112 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000029 (ops 141-145)
I20260812 06:17:07.291153 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000030 (ops 146-150)
I20260812 06:17:07.291194 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000031 (ops 151-155)
I20260812 06:17:07.291234 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000032 (ops 156-160)
I20260812 06:17:07.291276 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000033 (ops 161-165)
I20260812 06:17:07.291317 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000034 (ops 166-170)
I20260812 06:17:07.291358 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000035 (ops 171-174)
I20260812 06:17:07.291397 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000036 (ops 175-179)
I20260812 06:17:07.291436 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000037 (ops 180-184)
I20260812 06:17:07.291476 25463 log.cc:1079] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: Deleting log segment in path: /tmp/dist-test-taskhf_CyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515416878374-24991-0/minicluster-data/ts-0-root/wals/05d204862512494784bca3914c5a6f02/wal-000000038 (ops 185-188)
I20260812 06:17:07.318240 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: LogGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:07.318774 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02): 507 bytes on disk
I20260812 06:17:07.319325 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: UndoDeltaBlockGCOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.319918 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=6.157687
I20260812 06:17:07.358520 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.038s	user 0.021s	sys 0.001s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10060,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:07.358970 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=2.188937
I20260812 06:17:07.369789 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.370589 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02): perf score=1.000000
I20260812 06:17:07.545954 24991 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.938s	user 1.830s	sys 0.183s
I20260812 06:17:07.611160 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: MajorDeltaCompactionOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.240s	user 0.183s	sys 0.057s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082162,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16882,"lbm_reads_lt_1ms":870,"lbm_write_time_us":42694,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":4000}
I20260812 06:17:07.611652 25556 maintenance_manager.cc:419] P ca67f3c062e14fec881747622365a832: Scheduling FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02): perf score=14.095187
I20260812 06:17:07.641637 24991 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.001s	sys 0.000s
I20260812 06:17:07.642182 24991 tablet_server.cc:179] TabletServer@127.24.103.193:0 shutting down...
I20260812 06:17:07.661701 25463 maintenance_manager.cc:643] P ca67f3c062e14fec881747622365a832: FlushDeltaMemStoresOp(05d204862512494784bca3914c5a6f02) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21969,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.662364 24991 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:07.662788 24991 tablet_replica.cc:333] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832: stopping tablet replica
I20260812 06:17:07.663794 24991 raft_consensus.cc:2243] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.664033 24991 raft_consensus.cc:2272] T 05d204862512494784bca3914c5a6f02 P ca67f3c062e14fec881747622365a832 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.670320 24991 tablet_server.cc:196] TabletServer@127.24.103.193:0 shutdown complete.
I20260812 06:17:07.697778 24991 master.cc:562] Master@127.24.103.254:40139 shutting down...
I20260812 06:17:07.701781 24991 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.701969 24991 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.702066 24991 tablet_replica.cc:333] T 00000000000000000000000000000000 P 93ecffd6149b4e9695adc7037fa9d2bd: stopping tablet replica
I20260812 06:17:07.714430 24991 master.cc:584] Master@127.24.103.254:40139 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5436 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10917 ms total)

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