[==========] 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:22.383488  2304 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.64.62:42691
I20260812 06:16:22.384465  2304 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:22.385054  2304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.391487  2309 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:22.391536  2304 server_base.cc:1061] running on GCE node
W20260812 06:16:22.391487  2310 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:22.391808  2312 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:22.392349  2304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.392475  2304 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:22.392520  2304 hybrid_clock.cc:648] HybridClock initialized: now 1786515382392518 us; error 0 us; skew 500 ppm
I20260812 06:16:22.394353  2304 webserver.cc:533] Webserver started at http://127.2.64.62:43429/ using document root <none> and password file <none>
I20260812 06:16:22.394908  2304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.395001  2304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.395237  2304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.396950  2304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/master-0-root/instance:
uuid: "34a45dba6dfd4236b834ea7d4bd72085"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-bxbt"
I20260812 06:16:22.400348  2304 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:22.402338  2317 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:22.403311  2304 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:22.403443  2304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/master-0-root
uuid: "34a45dba6dfd4236b834ea7d4bd72085"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-bxbt"
I20260812 06:16:22.403548  2304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-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:22.423950  2304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.424556  2304 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:22.424754  2304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.433737  2304 rpc_server.cc:307] RPC server started. Bound to: 127.2.64.62:42691
I20260812 06:16:22.433745  2369 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.64.62:42691 every 8 connection(s)
I20260812 06:16:22.435895  2370 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:22.440975  2370 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: Bootstrap starting.
I20260812 06:16:22.443140  2370 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.444015  2370 log.cc:826] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:22.445631  2370 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: No bootstrap required, opened a new log
I20260812 06:16:22.448249  2370 raft_consensus.cc:359] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "34a45dba6dfd4236b834ea7d4bd72085" member_type: VOTER }
I20260812 06:16:22.448408  2370 raft_consensus.cc:385] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.448448  2370 raft_consensus.cc:740] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 34a45dba6dfd4236b834ea7d4bd72085, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.448925  2370 consensus_queue.cc:260] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [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: "34a45dba6dfd4236b834ea7d4bd72085" member_type: VOTER }
I20260812 06:16:22.449048  2370 raft_consensus.cc:399] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.449091  2370 raft_consensus.cc:493] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.449173  2370 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.449856  2370 raft_consensus.cc:515] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "34a45dba6dfd4236b834ea7d4bd72085" member_type: VOTER }
I20260812 06:16:22.450212  2370 leader_election.cc:304] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [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: 34a45dba6dfd4236b834ea7d4bd72085; no voters: 
I20260812 06:16:22.450457  2370 leader_election.cc:290] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.450598  2373 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.450874  2373 raft_consensus.cc:697] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 1 LEADER]: Becoming Leader. State: Replica: 34a45dba6dfd4236b834ea7d4bd72085, State: Running, Role: LEADER
I20260812 06:16:22.451248  2373 consensus_queue.cc:237] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [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: "34a45dba6dfd4236b834ea7d4bd72085" member_type: VOTER }
I20260812 06:16:22.451388  2370 sys_catalog.cc:565] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:22.453105  2375 sys_catalog.cc:455] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 34a45dba6dfd4236b834ea7d4bd72085. Latest consensus state: current_term: 1 leader_uuid: "34a45dba6dfd4236b834ea7d4bd72085" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "34a45dba6dfd4236b834ea7d4bd72085" member_type: VOTER } }
I20260812 06:16:22.453230  2375 sys_catalog.cc:458] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.453562  2374 sys_catalog.cc:455] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "34a45dba6dfd4236b834ea7d4bd72085" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "34a45dba6dfd4236b834ea7d4bd72085" member_type: VOTER } }
I20260812 06:16:22.453649  2374 sys_catalog.cc:458] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.453747  2304 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:22.455663  2388 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:22.455783  2388 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:22.455874  2386 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:22.456838  2386 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:22.461730  2386 catalog_manager.cc:1383] Generated new cluster ID: bbf8ea7479324c3cb5f1cfd5f9944cd6
I20260812 06:16:22.461848  2386 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:22.477451  2386 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:22.478264  2386 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:22.490145  2386 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: Generated new TSK 0
I20260812 06:16:22.490823  2386 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:22.518679  2304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.521729  2392 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:22.521780  2393 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:22.521924  2395 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:22.522061  2304 server_base.cc:1061] running on GCE node
I20260812 06:16:22.522219  2304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.522280  2304 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:22.522310  2304 hybrid_clock.cc:648] HybridClock initialized: now 1786515382522308 us; error 0 us; skew 500 ppm
I20260812 06:16:22.523290  2304 webserver.cc:533] Webserver started at http://127.2.64.1:33747/ using document root <none> and password file <none>
I20260812 06:16:22.523546  2304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.523636  2304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.523743  2304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.524161  2304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/instance:
uuid: "e6cd999663a94b44a08cd4c595d08ab5"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-bxbt"
I20260812 06:16:22.525715  2304 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:22.526712  2400 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:22.527000  2304 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:22.527062  2304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root
uuid: "e6cd999663a94b44a08cd4c595d08ab5"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-bxbt"
I20260812 06:16:22.527150  2304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-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:22.575802  2304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.576318  2304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.576817  2304 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:22.577696  2304 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:22.577750  2304 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.577792  2304 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:22.577867  2304 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.584444  2304 rpc_server.cc:307] RPC server started. Bound to: 127.2.64.1:45439
I20260812 06:16:22.584477  2463 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.64.1:45439 every 8 connection(s)
I20260812 06:16:22.597947  2464 heartbeater.cc:344] Connected to a master server at 127.2.64.62:42691
I20260812 06:16:22.598201  2464 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:22.598668  2464 heartbeater.cc:507] Master 127.2.64.62:42691 requested a full tablet report, sending...
I20260812 06:16:22.600117  2334 ts_manager.cc:194] Registered new tserver with Master: e6cd999663a94b44a08cd4c595d08ab5 (127.2.64.1:45439)
I20260812 06:16:22.600692  2304 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015609541s
I20260812 06:16:22.601521  2334 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47788
I20260812 06:16:22.611263  2334 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47792:
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:22.624589  2428 tablet_service.cc:1511] Processing CreateTablet for tablet 350e883085394f2796141aeb4ef55836 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bb2abafc7fac49ac97e9b47ca96abbb3]), partition=
I20260812 06:16:22.625116  2428 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 350e883085394f2796141aeb4ef55836. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:22.627346  2476 tablet_bootstrap.cc:492] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Bootstrap starting.
I20260812 06:16:22.628228  2476 tablet_bootstrap.cc:654] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.629328  2476 tablet_bootstrap.cc:492] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: No bootstrap required, opened a new log
I20260812 06:16:22.629462  2476 ts_tablet_manager.cc:1403] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:22.629881  2476 raft_consensus.cc:359] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6cd999663a94b44a08cd4c595d08ab5" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 45439 } }
I20260812 06:16:22.629978  2476 raft_consensus.cc:385] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.630002  2476 raft_consensus.cc:740] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e6cd999663a94b44a08cd4c595d08ab5, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.630167  2476 consensus_queue.cc:260] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [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: "e6cd999663a94b44a08cd4c595d08ab5" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 45439 } }
I20260812 06:16:22.630246  2476 raft_consensus.cc:399] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.630308  2476 raft_consensus.cc:493] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.630371  2476 raft_consensus.cc:3060] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.631068  2476 raft_consensus.cc:515] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6cd999663a94b44a08cd4c595d08ab5" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 45439 } }
I20260812 06:16:22.631223  2476 leader_election.cc:304] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [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: e6cd999663a94b44a08cd4c595d08ab5; no voters: 
I20260812 06:16:22.631449  2476 leader_election.cc:290] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.631605  2478 raft_consensus.cc:2804] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.631827  2476 ts_tablet_manager.cc:1434] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:22.631856  2478 raft_consensus.cc:697] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 1 LEADER]: Becoming Leader. State: Replica: e6cd999663a94b44a08cd4c595d08ab5, State: Running, Role: LEADER
I20260812 06:16:22.632236  2464 heartbeater.cc:499] Master 127.2.64.62:42691 was elected leader, sending a full tablet report...
I20260812 06:16:22.632251  2478 consensus_queue.cc:237] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [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: "e6cd999663a94b44a08cd4c595d08ab5" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 45439 } }
I20260812 06:16:22.634855  2334 catalog_manager.cc:5719] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 reported cstate change: term changed from 0 to 1, leader changed from <none> to e6cd999663a94b44a08cd4c595d08ab5 (127.2.64.1). New cstate: current_term: 1 leader_uuid: "e6cd999663a94b44a08cd4c595d08ab5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6cd999663a94b44a08cd4c595d08ab5" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 45439 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:22.692476  2304 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.020s	sys 0.007s
I20260812 06:16:22.835561  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushMRSOp(350e883085394f2796141aeb4ef55836): perf score=19.054940
I20260812 06:16:23.016937  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushMRSOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.181s	user 0.118s	sys 0.060s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":231,"delete_count":0,"dirs.queue_time_us":931,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":851,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44316,"lbm_writes_lt_1ms":767,"mutex_wait_us":400,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":175872,"thread_start_us":158,"threads_started":1,"update_count":1550}
I20260812 06:16:23.018250  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling LogGCOp(350e883085394f2796141aeb4ef55836): free 20743880 bytes of WAL
I20260812 06:16:23.018561  2405 log_reader.cc:385] T 350e883085394f2796141aeb4ef55836: removed 2 log segments from log reader
I20260812 06:16:23.018635  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000001 (ops 1-6)
I20260812 06:16:23.018698  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000002 (ops 7-11)
I20260812 06:16:23.023555  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: LogGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:23.023904  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836): 16411393 bytes on disk
I20260812 06:16:23.024578  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:16:23.024968  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=4.173312
I20260812 06:16:23.048133  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.023s	user 0.015s	sys 0.008s Metrics: {"bytes_written":5415437,"delete_count":0,"lbm_write_time_us":6963,"lbm_writes_lt_1ms":135,"reinsert_count":0,"update_count":660}
I20260812 06:16:23.048663  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=1.196750
I20260812 06:16:23.060429  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":3652,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:16:23.060902  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:23.237900  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.176s	user 0.124s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774770,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":687,"lbm_read_time_us":12810,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29332,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":414,"threads_started":5,"update_count":2500}
I20260812 06:16:23.238546  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:23.284363  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21365,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.284868  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:23.301424  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.301913  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:23.423650  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.122s	user 0.110s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":291,"lbm_read_time_us":8523,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24681,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:16:23.424149  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:23.470127  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.046s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22441,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.470647  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:23.485801  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.486438  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:23.609274  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.123s	user 0.119s	sys 0.003s 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":1063,"lbm_read_time_us":8485,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22716,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:23.609978  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:23.649309  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15423,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.649899  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:23.661537  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.662117  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:23.778371  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.116s	user 0.096s	sys 0.020s 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":159,"lbm_read_time_us":7702,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22603,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:16:23.779019  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:23.817523  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.038s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14345,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.818215  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:23.829314  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.829952  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:23.979813  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.150s	user 0.093s	sys 0.056s 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":984,"lbm_read_time_us":10037,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24951,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:23.980599  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:24.013921  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.033s	user 0.030s	sys 0.001s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.014364  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:24.028640  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.029174  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:24.154364  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.125s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":601,"lbm_read_time_us":7805,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25449,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.155083  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:24.201128  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.046s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15357,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.201702  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:24.212153  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.212675  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushMRSOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:24.239925  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushMRSOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.027s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1390,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1711,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:24.240746  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling LogGCOp(350e883085394f2796141aeb4ef55836): free 116849526 bytes of WAL
I20260812 06:16:24.241025  2405 log_reader.cc:385] T 350e883085394f2796141aeb4ef55836: removed 12 log segments from log reader
I20260812 06:16:24.241087  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000003 (ops 12-16)
I20260812 06:16:24.241127  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000004 (ops 17-21)
I20260812 06:16:24.241154  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000005 (ops 22-26)
I20260812 06:16:24.241178  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000006 (ops 27-30)
I20260812 06:16:24.241204  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000007 (ops 31-35)
I20260812 06:16:24.241226  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000008 (ops 36-40)
I20260812 06:16:24.241248  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000009 (ops 41-44)
I20260812 06:16:24.241281  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000010 (ops 45-49)
I20260812 06:16:24.241317  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000011 (ops 50-54)
I20260812 06:16:24.241348  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000012 (ops 55-58)
I20260812 06:16:24.241377  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000013 (ops 59-63)
I20260812 06:16:24.241405  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000014 (ops 64-68)
I20260812 06:16:24.265671  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: LogGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.025s	user 0.005s	sys 0.018s Metrics: {}
I20260812 06:16:24.266103  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:24.283218  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.017s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.283624  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836): 462 bytes on disk
I20260812 06:16:24.284065  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836) 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:24.284490  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:24.294394  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.294781  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:24.456758  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.162s	user 0.123s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":762,"lbm_read_time_us":11325,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31891,"lbm_writes_lt_1ms":643,"mutex_wait_us":249,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:16:24.457232  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=14.095187
I20260812 06:16:24.518150  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.061s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22446,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.518630  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:24.529627  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.530068  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:24.678671  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.148s	user 0.103s	sys 0.043s 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":377,"lbm_read_time_us":11428,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28855,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2500}
I20260812 06:16:24.679239  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=12.110812
I20260812 06:16:24.724195  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.045s	user 0.030s	sys 0.011s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":17947,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:16:24.724833  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=1.196750
I20260812 06:16:24.738006  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.013s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2871909,"delete_count":0,"lbm_write_time_us":3889,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:16:24.738525  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:24.883699  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.145s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":434,"cfile_cache_miss_bytes":20754302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":8509,"lbm_reads_lt_1ms":466,"lbm_write_time_us":24252,"lbm_writes_lt_1ms":445,"mutex_wait_us":270,"peak_mem_usage":50771398,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2010}
I20260812 06:16:24.884476  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=14.095187
I20260812 06:16:24.933914  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.049s	user 0.015s	sys 0.032s Metrics: {"bytes_written":16327857,"delete_count":0,"lbm_write_time_us":22290,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":1990}
I20260812 06:16:24.934512  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:24.952684  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.018s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.953357  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:25.127570  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.174s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":530,"cfile_cache_miss_bytes":24692643,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1624,"lbm_read_time_us":12219,"lbm_reads_lt_1ms":570,"lbm_write_time_us":31484,"lbm_writes_lt_1ms":541,"mutex_wait_us":694,"peak_mem_usage":61993446,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2490}
I20260812 06:16:25.128221  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:25.162518  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.034s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12389539,"delete_count":0,"lbm_write_time_us":14854,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1510}
I20260812 06:16:25.163048  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:25.184297  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.021s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":6316,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:16:25.184924  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:25.312865  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.128s	user 0.087s	sys 0.038s 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":878,"lbm_read_time_us":8140,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25892,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":64256,"update_count":2000}
I20260812 06:16:25.313678  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=11.118625
I20260812 06:16:25.343601  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.030s	user 0.008s	sys 0.019s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":13119,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:25.344161  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:25.362922  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5396,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.363540  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:25.482434  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.119s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1147,"lbm_read_time_us":6758,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24089,"lbm_writes_lt_1ms":443,"mutex_wait_us":440,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:25.483186  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=11.118625
I20260812 06:16:25.520298  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.037s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14259,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:25.520867  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:25.544245  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.023s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5385,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.544703  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:25.555979  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.556617  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushMRSOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:25.585067  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushMRSOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1316,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1460,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:25.585843  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling LogGCOp(350e883085394f2796141aeb4ef55836): free 120100344 bytes of WAL
I20260812 06:16:25.586081  2405 log_reader.cc:385] T 350e883085394f2796141aeb4ef55836: removed 12 log segments from log reader
I20260812 06:16:25.586128  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000015 (ops 69-72)
I20260812 06:16:25.586158  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000016 (ops 73-77)
I20260812 06:16:25.586223  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000017 (ops 78-82)
I20260812 06:16:25.586266  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000018 (ops 83-86)
I20260812 06:16:25.586323  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000019 (ops 87-91)
I20260812 06:16:25.586369  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000020 (ops 92-96)
I20260812 06:16:25.586411  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000021 (ops 97-101)
I20260812 06:16:25.586454  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000022 (ops 102-106)
I20260812 06:16:25.586491  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000023 (ops 107-110)
I20260812 06:16:25.586530  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000024 (ops 111-115)
I20260812 06:16:25.586572  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000025 (ops 116-120)
I20260812 06:16:25.586611  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000026 (ops 121-125)
I20260812 06:16:25.611323  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: LogGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:25.611806  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=3.181125
I20260812 06:16:25.623545  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:25.624002  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:25.633177  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3557,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.633572  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836): 463 bytes on disk
I20260812 06:16:25.633939  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:16:25.634389  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:25.819363  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.185s	user 0.139s	sys 0.044s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1076,"lbm_read_time_us":14377,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34909,"lbm_writes_lt_1ms":743,"mutex_wait_us":739,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":100,"threads_started":1,"update_count":3500}
I20260812 06:16:25.820155  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=14.095187
I20260812 06:16:25.873342  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.052s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24037,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.874168  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:25.888228  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.888726  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:26.047888  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.159s	user 0.111s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1046,"lbm_read_time_us":9561,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29956,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:16:26.048702  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=14.095187
I20260812 06:16:26.101070  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.052s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23674,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.101677  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:26.239259  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.137s	user 0.083s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":778,"lbm_read_time_us":8979,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22519,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:16:26.239915  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=14.095187
I20260812 06:16:26.293851  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.054s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20828,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.294397  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:26.305169  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.305658  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:26.485513  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.180s	user 0.144s	sys 0.029s 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":209,"lbm_read_time_us":12073,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32677,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:16:26.486271  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=14.095187
I20260812 06:16:26.541692  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.055s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20972,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.542229  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:26.553002  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.553421  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:26.722858  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.169s	user 0.127s	sys 0.041s 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":331,"lbm_read_time_us":11473,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29355,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:26.723423  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=11.118625
I20260812 06:16:26.766901  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.043s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19217,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:26.767495  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:26.789359  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.022s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4935,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:26.789824  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:26.809953  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.810515  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:26.990267  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.180s	user 0.116s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":340,"lbm_read_time_us":14284,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29250,"lbm_writes_lt_1ms":543,"mutex_wait_us":120,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:26.992798  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=10.126437
I20260812 06:16:27.030397  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.037s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17185,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.031056  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:27.050501  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7021,"lbm_writes_lt_1ms":103,"mutex_wait_us":3,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.051023  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushMRSOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:27.080026  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushMRSOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1242,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1652,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:27.080888  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling LogGCOp(350e883085394f2796141aeb4ef55836): free 124257494 bytes of WAL
I20260812 06:16:27.081306  2405 log_reader.cc:385] T 350e883085394f2796141aeb4ef55836: removed 12 log segments from log reader
I20260812 06:16:27.081457  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000027 (ops 126-130)
I20260812 06:16:27.081597  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000028 (ops 131-135)
I20260812 06:16:27.081707  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000029 (ops 136-140)
I20260812 06:16:27.081801  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000030 (ops 141-145)
I20260812 06:16:27.081899  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000031 (ops 146-150)
I20260812 06:16:27.081990  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000032 (ops 151-155)
I20260812 06:16:27.082091  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000033 (ops 156-160)
I20260812 06:16:27.082180  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000034 (ops 161-165)
I20260812 06:16:27.082278  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000035 (ops 166-170)
I20260812 06:16:27.082392  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000036 (ops 171-175)
I20260812 06:16:27.082501  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000037 (ops 176-180)
I20260812 06:16:27.082595  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000038 (ops 181-184)
I20260812 06:16:27.111835  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: LogGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:27.112310  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=6.157687
I20260812 06:16:27.145107  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.033s	user 0.012s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10222,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:27.145694  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling LogGCOp(350e883085394f2796141aeb4ef55836): free 8767138 bytes of WAL
I20260812 06:16:27.145938  2405 log_reader.cc:385] T 350e883085394f2796141aeb4ef55836: removed 1 log segments from log reader
I20260812 06:16:27.146026  2405 log.cc:1079] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/350e883085394f2796141aeb4ef55836/wal-000000039 (ops 185-189)
I20260812 06:16:27.147734  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: LogGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:27.148061  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:27.349166  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.201s	user 0.128s	sys 0.062s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":297,"lbm_read_time_us":14209,"lbm_reads_lt_1ms":665,"lbm_write_time_us":31109,"lbm_writes_lt_1ms":643,"mutex_wait_us":19,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:16:27.349978  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836): 482 bytes on disk
I20260812 06:16:27.350566  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: UndoDeltaBlockGCOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:16:27.351522  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=18.063937
I20260812 06:16:27.396159  2304 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.704s	user 1.761s	sys 0.135s
I20260812 06:16:27.402490  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":24139,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:27.402895  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836): perf score=2.188937
I20260812 06:16:27.412321  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: FlushDeltaMemStoresOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.412729  2465 maintenance_manager.cc:419] P e6cd999663a94b44a08cd4c595d08ab5: Scheduling MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836): perf score=1.000000
I20260812 06:16:27.441119  2304 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.044s	user 0.002s	sys 0.000s
I20260812 06:16:27.441798  2304 tablet_server.cc:179] TabletServer@127.2.64.1:0 shutting down...
I20260812 06:16:27.575613  2405 maintenance_manager.cc:643] P e6cd999663a94b44a08cd4c595d08ab5: MajorDeltaCompactionOp(350e883085394f2796141aeb4ef55836) complete. Timing: real 0.163s	user 0.122s	sys 0.040s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614713,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":938,"lbm_read_time_us":9555,"lbm_reads_lt_1ms":618,"lbm_write_time_us":27135,"lbm_writes_lt_1ms":643,"mutex_wait_us":378,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":3000}
I20260812 06:16:27.576387  2304 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:27.576835  2304 tablet_replica.cc:333] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5: stopping tablet replica
I20260812 06:16:27.577097  2304 raft_consensus.cc:2243] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:27.577380  2304 raft_consensus.cc:2272] T 350e883085394f2796141aeb4ef55836 P e6cd999663a94b44a08cd4c595d08ab5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:27.593989  2304 tablet_server.cc:196] TabletServer@127.2.64.1:0 shutdown complete.
I20260812 06:16:27.628226  2304 master.cc:562] Master@127.2.64.62:42691 shutting down...
I20260812 06:16:27.632288  2304 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:27.632474  2304 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:27.632570  2304 tablet_replica.cc:333] T 00000000000000000000000000000000 P 34a45dba6dfd4236b834ea7d4bd72085: stopping tablet replica
I20260812 06:16:27.644727  2304 master.cc:584] Master@127.2.64.62:42691 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5345 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:27.728081  2304 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.64.62:35619
I20260812 06:16:27.728479  2304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:27.730530  2496 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:27.730579  2304 server_base.cc:1061] running on GCE node
W20260812 06:16:27.730576  2498 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:27.730530  2495 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:27.730984  2304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:27.731029  2304 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:27.731045  2304 hybrid_clock.cc:648] HybridClock initialized: now 1786515387731045 us; error 0 us; skew 500 ppm
I20260812 06:16:27.732021  2304 webserver.cc:533] Webserver started at http://127.2.64.62:38195/ using document root <none> and password file <none>
I20260812 06:16:27.732187  2304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:27.732244  2304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:27.732338  2304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:27.732800  2304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/master-0-root/instance:
uuid: "a5ff2ae9e6e94e7ba869f4801d25861c"
format_stamp: "Formatted at 2026-08-12 06:16:27 on dist-test-slave-bxbt"
I20260812 06:16:27.734297  2304 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:27.735246  2503 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:27.735505  2304 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:27.735598  2304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/master-0-root
uuid: "a5ff2ae9e6e94e7ba869f4801d25861c"
format_stamp: "Formatted at 2026-08-12 06:16:27 on dist-test-slave-bxbt"
I20260812 06:16:27.735707  2304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-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:27.741732  2304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:27.742057  2304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:27.746275  2304 rpc_server.cc:307] RPC server started. Bound to: 127.2.64.62:35619
I20260812 06:16:27.748591  2555 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.64.62:35619 every 8 connection(s)
I20260812 06:16:27.759291  2556 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:27.761308  2556 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c: Bootstrap starting.
I20260812 06:16:27.762115  2556 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:27.763203  2556 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c: No bootstrap required, opened a new log
I20260812 06:16:27.763622  2556 raft_consensus.cc:359] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ff2ae9e6e94e7ba869f4801d25861c" member_type: VOTER }
I20260812 06:16:27.763760  2556 raft_consensus.cc:385] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:27.763859  2556 raft_consensus.cc:740] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a5ff2ae9e6e94e7ba869f4801d25861c, State: Initialized, Role: FOLLOWER
I20260812 06:16:27.764041  2556 consensus_queue.cc:260] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [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: "a5ff2ae9e6e94e7ba869f4801d25861c" member_type: VOTER }
I20260812 06:16:27.764142  2556 raft_consensus.cc:399] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:27.764189  2556 raft_consensus.cc:493] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:27.764243  2556 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:27.764915  2556 raft_consensus.cc:515] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ff2ae9e6e94e7ba869f4801d25861c" member_type: VOTER }
I20260812 06:16:27.765066  2556 leader_election.cc:304] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [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: a5ff2ae9e6e94e7ba869f4801d25861c; no voters: 
I20260812 06:16:27.765267  2556 leader_election.cc:290] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:27.765396  2559 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:27.765650  2559 raft_consensus.cc:697] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 1 LEADER]: Becoming Leader. State: Replica: a5ff2ae9e6e94e7ba869f4801d25861c, State: Running, Role: LEADER
I20260812 06:16:27.765738  2556 sys_catalog.cc:565] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:27.765818  2559 consensus_queue.cc:237] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [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: "a5ff2ae9e6e94e7ba869f4801d25861c" member_type: VOTER }
I20260812 06:16:27.766283  2560 sys_catalog.cc:455] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a5ff2ae9e6e94e7ba869f4801d25861c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ff2ae9e6e94e7ba869f4801d25861c" member_type: VOTER } }
I20260812 06:16:27.766307  2561 sys_catalog.cc:455] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [sys.catalog]: SysCatalogTable state changed. Reason: New leader a5ff2ae9e6e94e7ba869f4801d25861c. Latest consensus state: current_term: 1 leader_uuid: "a5ff2ae9e6e94e7ba869f4801d25861c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ff2ae9e6e94e7ba869f4801d25861c" member_type: VOTER } }
I20260812 06:16:27.766405  2560 sys_catalog.cc:458] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:27.766415  2561 sys_catalog.cc:458] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:27.767067  2565 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:27.767856  2565 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:27.768038  2304 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:27.769730  2565 catalog_manager.cc:1383] Generated new cluster ID: fa9a012386474d849a65585173b258a2
I20260812 06:16:27.769794  2565 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:27.779574  2565 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:27.780148  2565 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:27.789283  2565 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c: Generated new TSK 0
I20260812 06:16:27.789464  2565 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:27.800495  2304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:27.802455  2578 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:27.802527  2580 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:27.802544  2577 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:27.802731  2304 server_base.cc:1061] running on GCE node
I20260812 06:16:27.802889  2304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:27.802942  2304 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:27.802958  2304 hybrid_clock.cc:648] HybridClock initialized: now 1786515387802959 us; error 0 us; skew 500 ppm
I20260812 06:16:27.803887  2304 webserver.cc:533] Webserver started at http://127.2.64.1:38419/ using document root <none> and password file <none>
I20260812 06:16:27.804072  2304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:27.804140  2304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:27.804220  2304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:27.804639  2304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/instance:
uuid: "8aca7e4de69d448e82b8d09537c14976"
format_stamp: "Formatted at 2026-08-12 06:16:27 on dist-test-slave-bxbt"
I20260812 06:16:27.806166  2304 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:27.807210  2585 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:27.807451  2304 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:27.807542  2304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root
uuid: "8aca7e4de69d448e82b8d09537c14976"
format_stamp: "Formatted at 2026-08-12 06:16:27 on dist-test-slave-bxbt"
I20260812 06:16:27.807632  2304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-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:27.816854  2304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:27.817214  2304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:27.817518  2304 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:27.817976  2304 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:27.818037  2304 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:27.818100  2304 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:27.818150  2304 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:27.822485  2304 rpc_server.cc:307] RPC server started. Bound to: 127.2.64.1:39271
I20260812 06:16:27.822516  2648 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.64.1:39271 every 8 connection(s)
I20260812 06:16:27.830354  2649 heartbeater.cc:344] Connected to a master server at 127.2.64.62:35619
I20260812 06:16:27.830458  2649 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:27.830660  2649 heartbeater.cc:507] Master 127.2.64.62:35619 requested a full tablet report, sending...
I20260812 06:16:27.831328  2520 ts_manager.cc:194] Registered new tserver with Master: 8aca7e4de69d448e82b8d09537c14976 (127.2.64.1:39271)
I20260812 06:16:27.831796  2304 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008874305s
I20260812 06:16:27.832267  2520 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50622
I20260812 06:16:27.838562  2520 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50628:
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:27.847028  2613 tablet_service.cc:1511] Processing CreateTablet for tablet 88aac0c518024e9da8b965f599eb8d02 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e66a9fdbaae846d6b12d0c936afdb688]), partition=
I20260812 06:16:27.847318  2613 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 88aac0c518024e9da8b965f599eb8d02. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:27.849448  2661 tablet_bootstrap.cc:492] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Bootstrap starting.
I20260812 06:16:27.850255  2661 tablet_bootstrap.cc:654] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:27.851353  2661 tablet_bootstrap.cc:492] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: No bootstrap required, opened a new log
I20260812 06:16:27.851480  2661 ts_tablet_manager.cc:1403] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:27.851976  2661 raft_consensus.cc:359] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8aca7e4de69d448e82b8d09537c14976" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 39271 } }
I20260812 06:16:27.852093  2661 raft_consensus.cc:385] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:27.852141  2661 raft_consensus.cc:740] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8aca7e4de69d448e82b8d09537c14976, State: Initialized, Role: FOLLOWER
I20260812 06:16:27.852286  2661 consensus_queue.cc:260] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [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: "8aca7e4de69d448e82b8d09537c14976" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 39271 } }
I20260812 06:16:27.852398  2661 raft_consensus.cc:399] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:27.852443  2661 raft_consensus.cc:493] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:27.852502  2661 raft_consensus.cc:3060] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:27.853322  2661 raft_consensus.cc:515] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8aca7e4de69d448e82b8d09537c14976" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 39271 } }
I20260812 06:16:27.853482  2661 leader_election.cc:304] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [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: 8aca7e4de69d448e82b8d09537c14976; no voters: 
I20260812 06:16:27.853698  2661 leader_election.cc:290] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:27.853825  2663 raft_consensus.cc:2804] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:27.854048  2649 heartbeater.cc:499] Master 127.2.64.62:35619 was elected leader, sending a full tablet report...
I20260812 06:16:27.854068  2663 raft_consensus.cc:697] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 1 LEADER]: Becoming Leader. State: Replica: 8aca7e4de69d448e82b8d09537c14976, State: Running, Role: LEADER
I20260812 06:16:27.854244  2663 consensus_queue.cc:237] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [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: "8aca7e4de69d448e82b8d09537c14976" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 39271 } }
I20260812 06:16:27.854343  2661 ts_tablet_manager.cc:1434] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:27.855587  2520 catalog_manager.cc:5719] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8aca7e4de69d448e82b8d09537c14976 (127.2.64.1). New cstate: current_term: 1 leader_uuid: "8aca7e4de69d448e82b8d09537c14976" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8aca7e4de69d448e82b8d09537c14976" member_type: VOTER last_known_addr { host: "127.2.64.1" port: 39271 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:27.915606  2304 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.012s	sys 0.012s
I20260812 06:16:28.073751  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushMRSOp(88aac0c518024e9da8b965f599eb8d02): perf score=20.047128
I20260812 06:16:28.240841  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushMRSOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.167s	user 0.127s	sys 0.036s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":918,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46672,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":3712,"update_count":1500}
I20260812 06:16:28.241461  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling LogGCOp(88aac0c518024e9da8b965f599eb8d02): free 20743880 bytes of WAL
I20260812 06:16:28.241694  2590 log_reader.cc:385] T 88aac0c518024e9da8b965f599eb8d02: removed 2 log segments from log reader
I20260812 06:16:28.241740  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000001 (ops 1-6)
I20260812 06:16:28.241797  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000002 (ops 7-11)
I20260812 06:16:28.245986  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: LogGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:28.246413  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:28.265821  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.019s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.266650  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02): 20513813 bytes on disk
I20260812 06:16:28.267040  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:16:28.267477  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:28.427212  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.160s	user 0.096s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":852,"lbm_read_time_us":10910,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24620,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":348,"threads_started":5,"update_count":2000}
I20260812 06:16:28.427934  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:28.480023  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.052s	user 0.045s	sys 0.005s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.480512  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:28.490778  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.491531  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:28.653864  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.162s	user 0.120s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":9766,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32562,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:16:28.654495  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:28.704420  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.050s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18067,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.704977  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:28.720022  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.720615  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:28.870497  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.150s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":9497,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31523,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:16:28.871258  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=11.118625
I20260812 06:16:28.901785  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.030s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":13364,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":307,"reinsert_count":0,"update_count":1525}
I20260812 06:16:28.902247  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:28.916636  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5057,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:16:28.917053  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:29.047436  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.130s	user 0.110s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":537,"lbm_read_time_us":9423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26625,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:16:29.047960  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=10.126437
I20260812 06:16:29.100904  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.053s	user 0.013s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16069,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.101400  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:29.111742  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.112323  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:29.250092  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.138s	user 0.081s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":10263,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21452,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:16:29.250705  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=10.126437
I20260812 06:16:29.287653  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.037s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15814,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.288237  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:29.300385  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.300822  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:29.422155  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":8534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23141,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:16:29.422843  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=10.126437
I20260812 06:16:29.463979  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19529,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.464524  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:29.482241  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.018s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:16:29.482729  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushMRSOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:29.536937  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushMRSOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.054s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1422,"drs_written":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1609,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:29.537603  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling LogGCOp(88aac0c518024e9da8b965f599eb8d02): free 121006437 bytes of WAL
I20260812 06:16:29.537825  2590 log_reader.cc:385] T 88aac0c518024e9da8b965f599eb8d02: removed 12 log segments from log reader
I20260812 06:16:29.537886  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000003 (ops 12-16)
I20260812 06:16:29.537938  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000004 (ops 17-21)
I20260812 06:16:29.537998  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000005 (ops 22-26)
I20260812 06:16:29.538040  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000006 (ops 27-30)
I20260812 06:16:29.538076  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000007 (ops 31-35)
I20260812 06:16:29.538110  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000008 (ops 36-40)
I20260812 06:16:29.538146  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000009 (ops 41-45)
I20260812 06:16:29.538182  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000010 (ops 46-50)
I20260812 06:16:29.538220  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000011 (ops 51-55)
I20260812 06:16:29.538257  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000012 (ops 56-60)
I20260812 06:16:29.538293  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000013 (ops 61-65)
I20260812 06:16:29.538331  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000014 (ops 66-70)
I20260812 06:16:29.562891  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: LogGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:29.563328  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02): 482 bytes on disk
I20260812 06:16:29.563858  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.564359  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=7.149875
I20260812 06:16:29.591133  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.027s	user 0.017s	sys 0.007s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11394,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:29.591665  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling LogGCOp(88aac0c518024e9da8b965f599eb8d02): free 12017927 bytes of WAL
I20260812 06:16:29.591935  2590 log_reader.cc:385] T 88aac0c518024e9da8b965f599eb8d02: removed 1 log segments from log reader
I20260812 06:16:29.591997  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000015 (ops 71-75)
I20260812 06:16:29.594825  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: LogGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:29.595156  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:29.610335  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5731,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:29.610795  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:29.804870  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.194s	user 0.149s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020737,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1193,"lbm_read_time_us":11593,"lbm_reads_lt_1ms":766,"lbm_write_time_us":39517,"lbm_writes_lt_1ms":743,"mutex_wait_us":606,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24064,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:16:29.805725  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=15.087375
I20260812 06:16:29.871161  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.065s	user 0.042s	sys 0.011s Metrics: {"bytes_written":16820148,"delete_count":0,"lbm_write_time_us":19894,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:29.871622  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=3.181125
I20260812 06:16:29.882674  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4348809,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:16:29.883061  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:29.891860  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":3370,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:16:29.892217  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:30.087298  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.195s	user 0.126s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":201,"lbm_read_time_us":13303,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31393,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":3000}
I20260812 06:16:30.087939  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:30.141024  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.053s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23821,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.141542  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:30.156174  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5164,"lbm_writes_lt_1ms":103,"mutex_wait_us":32,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.157006  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:30.318697  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.162s	user 0.120s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11733,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27394,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:30.319300  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:30.380425  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.061s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20104,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.381068  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:30.398324  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.398962  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:30.575083  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.176s	user 0.122s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29702,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:30.575995  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=11.118625
I20260812 06:16:30.619601  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.043s	user 0.020s	sys 0.014s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14289,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:30.620242  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:30.643818  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.023s	user 0.015s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.644357  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:30.654075  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3628,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.654572  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:30.859915  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.205s	user 0.160s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":285,"lbm_read_time_us":14198,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29291,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:16:30.860773  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:30.907452  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.046s	user 0.034s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19889,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.908082  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:30.920059  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.920783  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushMRSOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:30.957800  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushMRSOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.037s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1497,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1542,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:30.958571  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling LogGCOp(88aac0c518024e9da8b965f599eb8d02): free 112239326 bytes of WAL
I20260812 06:16:30.958854  2590 log_reader.cc:385] T 88aac0c518024e9da8b965f599eb8d02: removed 11 log segments from log reader
I20260812 06:16:30.958922  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000016 (ops 76-80)
I20260812 06:16:30.958961  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000017 (ops 81-84)
I20260812 06:16:30.958985  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000018 (ops 85-89)
I20260812 06:16:30.959009  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000019 (ops 90-94)
I20260812 06:16:30.959035  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000020 (ops 95-99)
I20260812 06:16:30.959069  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000021 (ops 100-104)
I20260812 06:16:30.959100  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000022 (ops 105-109)
I20260812 06:16:30.959122  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000023 (ops 110-114)
I20260812 06:16:30.959151  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000024 (ops 115-119)
I20260812 06:16:30.959182  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000025 (ops 120-124)
I20260812 06:16:30.959218  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000026 (ops 125-129)
I20260812 06:16:30.986581  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: LogGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:30.987079  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:31.002941  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.003402  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:31.202926  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.199s	user 0.131s	sys 0.058s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":845,"lbm_read_time_us":13042,"lbm_reads_lt_1ms":665,"lbm_write_time_us":32001,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:16:31.204037  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=18.063937
I20260812 06:16:31.262663  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.058s	user 0.042s	sys 0.013s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26803,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:31.263216  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:31.278492  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.279014  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:31.491863  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.213s	user 0.135s	sys 0.070s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":823,"lbm_read_time_us":13514,"lbm_reads_lt_1ms":668,"lbm_write_time_us":34862,"lbm_writes_lt_1ms":643,"mutex_wait_us":101,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":3000}
I20260812 06:16:31.492834  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=16.079562
I20260812 06:16:31.546751  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.054s	user 0.020s	sys 0.029s Metrics: {"bytes_written":17681651,"delete_count":0,"lbm_write_time_us":22690,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:16:31.547350  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:31.563452  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":5213,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:16:31.563931  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02): 448 bytes on disk
I20260812 06:16:31.564368  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:31.564837  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:31.574683  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.575078  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:31.759840  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.185s	user 0.123s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918185,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":224,"lbm_read_time_us":12402,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29658,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":3000}
I20260812 06:16:31.760694  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:31.810099  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.049s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21137,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.810714  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:31.829103  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.829562  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:32.012555  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.183s	user 0.123s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":691,"lbm_read_time_us":12266,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31540,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:16:32.013250  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:32.074170  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.061s	user 0.021s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19420,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.074790  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:32.092028  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.096041  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:32.275386  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.179s	user 0.130s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1275,"lbm_read_time_us":12477,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30162,"lbm_writes_lt_1ms":543,"mutex_wait_us":373,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:16:32.276043  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=14.095187
I20260812 06:16:32.334982  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.059s	user 0.036s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.335546  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:32.346565  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.347041  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushMRSOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:32.389456  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushMRSOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.042s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":160,"dirs.run_wall_time_us":1193,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2265,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:32.390156  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling LogGCOp(88aac0c518024e9da8b965f599eb8d02): free 120100590 bytes of WAL
I20260812 06:16:32.390381  2590 log_reader.cc:385] T 88aac0c518024e9da8b965f599eb8d02: removed 12 log segments from log reader
I20260812 06:16:32.390429  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000027 (ops 130-134)
I20260812 06:16:32.390457  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000028 (ops 135-139)
I20260812 06:16:32.390522  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000029 (ops 140-144)
I20260812 06:16:32.390568  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000030 (ops 145-149)
I20260812 06:16:32.390630  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000031 (ops 150-154)
I20260812 06:16:32.390668  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000032 (ops 155-158)
I20260812 06:16:32.390710  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000033 (ops 159-163)
I20260812 06:16:32.390749  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000034 (ops 164-168)
I20260812 06:16:32.390789  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000035 (ops 169-172)
I20260812 06:16:32.390829  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000036 (ops 173-177)
I20260812 06:16:32.390870  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000037 (ops 178-182)
I20260812 06:16:32.390911  2590 log.cc:1079] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: Deleting log segment in path: /tmp/dist-test-task0rvu9g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382372878-2304-0/minicluster-data/ts-0-root/wals/88aac0c518024e9da8b965f599eb8d02/wal-000000038 (ops 183-186)
I20260812 06:16:32.414988  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: LogGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:32.415469  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:32.432744  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.017s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.433221  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:32.445220  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.445732  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:32.663517  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.218s	user 0.152s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":608,"lbm_read_time_us":15312,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36231,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":31232,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:16:32.664256  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=18.063937
I20260812 06:16:32.709326  2304 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.794s	user 1.770s	sys 0.198s
I20260812 06:16:32.726589  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.062s	user 0.025s	sys 0.035s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31456,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:16:32.727185  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02): perf score=2.188937
I20260812 06:16:32.744807  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: FlushDeltaMemStoresOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.745354  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02): 447 bytes on disk
I20260812 06:16:32.745828  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: UndoDeltaBlockGCOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.746801  2650 maintenance_manager.cc:419] P 8aca7e4de69d448e82b8d09537c14976: Scheduling MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02): perf score=1.000000
I20260812 06:16:32.751536  2304 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.042s	user 0.001s	sys 0.000s
I20260812 06:16:32.752158  2304 tablet_server.cc:179] TabletServer@127.2.64.1:0 shutting down...
I20260812 06:16:32.906872  2590 maintenance_manager.cc:643] P 8aca7e4de69d448e82b8d09537c14976: MajorDeltaCompactionOp(88aac0c518024e9da8b965f599eb8d02) complete. Timing: real 0.160s	user 0.130s	sys 0.029s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614712,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":483,"lbm_read_time_us":12012,"lbm_reads_lt_1ms":618,"lbm_write_time_us":28789,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":3000}
I20260812 06:16:32.908082  2304 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:32.908357  2304 tablet_replica.cc:333] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976: stopping tablet replica
I20260812 06:16:32.908533  2304 raft_consensus.cc:2243] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:32.908743  2304 raft_consensus.cc:2272] T 88aac0c518024e9da8b965f599eb8d02 P 8aca7e4de69d448e82b8d09537c14976 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:32.913741  2304 tablet_server.cc:196] TabletServer@127.2.64.1:0 shutdown complete.
I20260812 06:16:32.959781  2304 master.cc:562] Master@127.2.64.62:35619 shutting down...
I20260812 06:16:32.963418  2304 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:32.963614  2304 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:32.963732  2304 tablet_replica.cc:333] T 00000000000000000000000000000000 P a5ff2ae9e6e94e7ba869f4801d25861c: stopping tablet replica
I20260812 06:16:32.976150  2304 master.cc:584] Master@127.2.64.62:35619 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5332 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10678 ms total)

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