[==========] 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.899569 13161 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.218.126:37701
I20260812 06:16:22.900542 13161 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.901189 13161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.907958 13172 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.908133 13173 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:22.908052 13161 server_base.cc:1061] running on GCE node
W20260812 06:16:22.908313 13176 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.908905 13161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.909008 13161 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.909039 13161 hybrid_clock.cc:648] HybridClock initialized: now 1786515382909038 us; error 0 us; skew 500 ppm
I20260812 06:16:22.911141 13161 webserver.cc:533] Webserver started at http://127.12.218.126:37001/ using document root <none> and password file <none>
I20260812 06:16:22.911870 13161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.911975 13161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.912220 13161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.914132 13161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/master-0-root/instance:
uuid: "ec04f2f902034e2cb524094e93efdb56"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-g170"
I20260812 06:16:22.918026 13161 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:22.920100 13187 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.921252 13161 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:22.921386 13161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/master-0-root
uuid: "ec04f2f902034e2cb524094e93efdb56"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-g170"
I20260812 06:16:22.921494 13161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-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.941576 13161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.942268 13161 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.942457 13161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.950224 13161 rpc_server.cc:307] RPC server started. Bound to: 127.12.218.126:37701
I20260812 06:16:22.950246 13274 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.218.126:37701 every 8 connection(s)
I20260812 06:16:22.952658 13275 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.958499 13275 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56: Bootstrap starting.
I20260812 06:16:22.961148 13275 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.962152 13275 log.cc:826] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:22.964092 13275 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56: No bootstrap required, opened a new log
I20260812 06:16:22.967458 13275 raft_consensus.cc:359] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec04f2f902034e2cb524094e93efdb56" member_type: VOTER }
I20260812 06:16:22.967661 13275 raft_consensus.cc:385] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.967743 13275 raft_consensus.cc:740] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ec04f2f902034e2cb524094e93efdb56, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.968415 13275 consensus_queue.cc:260] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [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: "ec04f2f902034e2cb524094e93efdb56" member_type: VOTER }
I20260812 06:16:22.968568 13275 raft_consensus.cc:399] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.968691 13275 raft_consensus.cc:493] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.968854 13275 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.969760 13275 raft_consensus.cc:515] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec04f2f902034e2cb524094e93efdb56" member_type: VOTER }
I20260812 06:16:22.970249 13275 leader_election.cc:304] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [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: ec04f2f902034e2cb524094e93efdb56; no voters: 
I20260812 06:16:22.970630 13275 leader_election.cc:290] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.970839 13286 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.971109 13286 raft_consensus.cc:697] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 1 LEADER]: Becoming Leader. State: Replica: ec04f2f902034e2cb524094e93efdb56, State: Running, Role: LEADER
I20260812 06:16:22.971501 13286 consensus_queue.cc:237] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [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: "ec04f2f902034e2cb524094e93efdb56" member_type: VOTER }
I20260812 06:16:22.971733 13275 sys_catalog.cc:565] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:22.973506 13289 sys_catalog.cc:455] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ec04f2f902034e2cb524094e93efdb56. Latest consensus state: current_term: 1 leader_uuid: "ec04f2f902034e2cb524094e93efdb56" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec04f2f902034e2cb524094e93efdb56" member_type: VOTER } }
I20260812 06:16:22.973527 13288 sys_catalog.cc:455] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ec04f2f902034e2cb524094e93efdb56" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec04f2f902034e2cb524094e93efdb56" member_type: VOTER } }
I20260812 06:16:22.973649 13289 sys_catalog.cc:458] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.973649 13288 sys_catalog.cc:458] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.974438 13161 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:22.974740 13300 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:22.977000 13300 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:22.981600 13300 catalog_manager.cc:1383] Generated new cluster ID: c0caabcf76964ff4855f4a898d00a0d2
I20260812 06:16:22.981669 13300 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:23.014673 13300 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:23.016000 13300 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:23.037235 13300 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56: Generated new TSK 0
I20260812 06:16:23.038023 13300 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:23.039502 13161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:23.042491 13314 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:23.042932 13313 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:23.043118 13161 server_base.cc:1061] running on GCE node
W20260812 06:16:23.043154 13318 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:23.043399 13161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:23.043478 13161 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:23.043505 13161 hybrid_clock.cc:648] HybridClock initialized: now 1786515383043505 us; error 0 us; skew 500 ppm
I20260812 06:16:23.044541 13161 webserver.cc:533] Webserver started at http://127.12.218.65:37073/ using document root <none> and password file <none>
I20260812 06:16:23.044747 13161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:23.044862 13161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:23.044950 13161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:23.045421 13161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/instance:
uuid: "46c7997de3d04fa78e0b91a1fad082cb"
format_stamp: "Formatted at 2026-08-12 06:16:23 on dist-test-slave-g170"
I20260812 06:16:23.047107 13161 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:23.048265 13324 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:23.048532 13161 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:23.048610 13161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root
uuid: "46c7997de3d04fa78e0b91a1fad082cb"
format_stamp: "Formatted at 2026-08-12 06:16:23 on dist-test-slave-g170"
I20260812 06:16:23.048714 13161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-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:23.066285 13161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:23.066843 13161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:23.067396 13161 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:23.068380 13161 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:23.068461 13161 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:23.068545 13161 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:23.068603 13161 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:23.076792 13161 rpc_server.cc:307] RPC server started. Bound to: 127.12.218.65:40469
I20260812 06:16:23.076836 13436 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.218.65:40469 every 8 connection(s)
I20260812 06:16:23.093215 13443 heartbeater.cc:344] Connected to a master server at 127.12.218.126:37701
I20260812 06:16:23.093459 13443 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:23.093915 13443 heartbeater.cc:507] Master 127.12.218.126:37701 requested a full tablet report, sending...
I20260812 06:16:23.095477 13214 ts_manager.cc:194] Registered new tserver with Master: 46c7997de3d04fa78e0b91a1fad082cb (127.12.218.65:40469)
I20260812 06:16:23.096382 13161 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01895847s
I20260812 06:16:23.097123 13214 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60324
I20260812 06:16:23.106426 13214 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60336:
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:23.124560 13380 tablet_service.cc:1511] Processing CreateTablet for tablet 045194e7023c452f986e5c901c33864e (DEFAULT_TABLE table=heavy-update-compaction-test [id=4a3ef3ff264e4c258a31e1defee3a1f4]), partition=
I20260812 06:16:23.125180 13380 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 045194e7023c452f986e5c901c33864e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:23.128486 13462 tablet_bootstrap.cc:492] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Bootstrap starting.
I20260812 06:16:23.130347 13462 tablet_bootstrap.cc:654] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:23.132666 13462 tablet_bootstrap.cc:492] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: No bootstrap required, opened a new log
I20260812 06:16:23.132826 13462 ts_tablet_manager.cc:1403] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Time spent bootstrapping tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:23.133464 13462 raft_consensus.cc:359] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "46c7997de3d04fa78e0b91a1fad082cb" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 40469 } }
I20260812 06:16:23.133603 13462 raft_consensus.cc:385] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:23.133656 13462 raft_consensus.cc:740] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 46c7997de3d04fa78e0b91a1fad082cb, State: Initialized, Role: FOLLOWER
I20260812 06:16:23.133806 13462 consensus_queue.cc:260] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [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: "46c7997de3d04fa78e0b91a1fad082cb" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 40469 } }
I20260812 06:16:23.133921 13462 raft_consensus.cc:399] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:23.133971 13462 raft_consensus.cc:493] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:23.134027 13462 raft_consensus.cc:3060] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:23.135021 13462 raft_consensus.cc:515] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "46c7997de3d04fa78e0b91a1fad082cb" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 40469 } }
I20260812 06:16:23.135182 13462 leader_election.cc:304] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [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: 46c7997de3d04fa78e0b91a1fad082cb; no voters: 
I20260812 06:16:23.135540 13462 leader_election.cc:290] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:23.135787 13466 raft_consensus.cc:2804] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:23.135993 13462 ts_tablet_manager.cc:1434] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:23.136473 13443 heartbeater.cc:499] Master 127.12.218.126:37701 was elected leader, sending a full tablet report...
I20260812 06:16:23.136583 13466 raft_consensus.cc:697] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 1 LEADER]: Becoming Leader. State: Replica: 46c7997de3d04fa78e0b91a1fad082cb, State: Running, Role: LEADER
I20260812 06:16:23.136844 13466 consensus_queue.cc:237] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [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: "46c7997de3d04fa78e0b91a1fad082cb" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 40469 } }
I20260812 06:16:23.139812 13214 catalog_manager.cc:5719] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb reported cstate change: term changed from 0 to 1, leader changed from <none> to 46c7997de3d04fa78e0b91a1fad082cb (127.12.218.65). New cstate: current_term: 1 leader_uuid: "46c7997de3d04fa78e0b91a1fad082cb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "46c7997de3d04fa78e0b91a1fad082cb" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 40469 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:23.231523 13161 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.079s	user 0.023s	sys 0.008s
I20260812 06:16:23.328109 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushMRSOp(045194e7023c452f986e5c901c33864e): perf score=11.117440
I20260812 06:16:23.482208 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushMRSOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.154s	user 0.103s	sys 0.039s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":233,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":854,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35176,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":151,"threads_started":1,"update_count":1450}
I20260812 06:16:23.483379 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling LogGCOp(045194e7023c452f986e5c901c33864e): free 8725963 bytes of WAL
I20260812 06:16:23.483683 13334 log_reader.cc:385] T 045194e7023c452f986e5c901c33864e: removed 1 log segments from log reader
I20260812 06:16:23.483748 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000001 (ops 1-6)
I20260812 06:16:23.486330 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: LogGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:23.486613 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e): 8616792 bytes on disk
I20260812 06:16:23.487200 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:16:23.487557 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:23.511386 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.024s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.511901 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:23.642364 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.130s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20221073,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":699,"lbm_read_time_us":7703,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25585,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":256,"threads_started":5,"update_count":1950}
I20260812 06:16:23.642918 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:23.684921 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.042s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17850,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.685438 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:23.697700 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.698324 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:23.816615 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.118s	user 0.078s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":419,"lbm_read_time_us":9129,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24516,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:16:23.817234 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:23.865022 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.048s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16178,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.865547 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:23.876914 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.877410 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:24.024744 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.147s	user 0.110s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":889,"lbm_read_time_us":11121,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24431,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.025306 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:24.062668 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.037s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16431,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.063184 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:24.172338 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.108s	user 0.072s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":275,"lbm_read_time_us":6152,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23306,"lbm_writes_lt_1ms":343,"mutex_wait_us":32,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":1500}
I20260812 06:16:24.173002 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:24.212126 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.039s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17208,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.212775 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:24.336061 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.123s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528780,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":443,"lbm_read_time_us":8387,"lbm_reads_lt_1ms":363,"lbm_write_time_us":25951,"lbm_writes_lt_1ms":343,"mutex_wait_us":21,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":1500}
I20260812 06:16:24.336894 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:24.377130 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.040s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17876,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.377631 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:24.388706 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.389312 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:24.512925 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.123s	user 0.106s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":547,"lbm_read_time_us":9574,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24182,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:16:24.513552 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:24.560173 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.046s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20380,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.560712 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:24.571959 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.572501 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:24.709085 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.136s	user 0.124s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1328,"lbm_read_time_us":8550,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28265,"lbm_writes_lt_1ms":443,"mutex_wait_us":449,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:16:24.709631 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:24.761430 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.052s	user 0.019s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21824,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.761982 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:24.775007 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.775600 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushMRSOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:24.806603 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushMRSOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1433,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1556,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:24.807569 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling LogGCOp(045194e7023c452f986e5c901c33864e): free 124710292 bytes of WAL
I20260812 06:16:24.807847 13334 log_reader.cc:385] T 045194e7023c452f986e5c901c33864e: removed 12 log segments from log reader
I20260812 06:16:24.807917 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000002 (ops 7-11)
I20260812 06:16:24.807961 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000003 (ops 12-16)
I20260812 06:16:24.807996 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000004 (ops 17-21)
I20260812 06:16:24.808032 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000005 (ops 22-26)
I20260812 06:16:24.808063 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000006 (ops 27-31)
I20260812 06:16:24.808096 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000007 (ops 32-36)
I20260812 06:16:24.808130 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000008 (ops 37-41)
I20260812 06:16:24.808161 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000009 (ops 42-46)
I20260812 06:16:24.808192 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000010 (ops 47-51)
I20260812 06:16:24.808226 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000011 (ops 52-56)
I20260812 06:16:24.808256 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000012 (ops 57-61)
I20260812 06:16:24.808290 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000013 (ops 62-66)
I20260812 06:16:24.839305 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: LogGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:24.839756 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e): 463 bytes on disk
I20260812 06:16:24.840291 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:24.840821 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=3.181125
I20260812 06:16:24.852632 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4544,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:24.853309 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:24.863071 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3779,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:24.863538 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:25.042788 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.179s	user 0.126s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":447,"lbm_read_time_us":11670,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36775,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:16:25.043421 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:25.098770 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.055s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26556,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.099273 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:25.116340 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.116904 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:25.279981 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.163s	user 0.096s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":157,"lbm_read_time_us":12416,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33382,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:25.280828 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:25.345713 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.065s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27598,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.346230 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:25.358309 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.358817 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:25.519629 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.161s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":10735,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30177,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30976,"update_count":2500}
I20260812 06:16:25.520337 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:25.565851 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.045s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20457,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.566421 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:25.722401 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.156s	user 0.090s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":942,"lbm_read_time_us":9821,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25219,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:16:25.723059 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:25.772362 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.049s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21383,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.772982 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:25.784686 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.785318 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:25.993268 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.208s	user 0.131s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":380,"lbm_read_time_us":11545,"lbm_reads_lt_1ms":572,"lbm_write_time_us":44943,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:16:25.993938 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:26.051950 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.058s	user 0.026s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22713,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.052495 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:26.068174 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.068810 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:26.237733 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.169s	user 0.133s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":77,"lbm_read_time_us":11261,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34849,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:26.238488 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=11.118625
I20260812 06:16:26.287773 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.049s	user 0.021s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21829,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:16:26.288326 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:26.305279 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.305876 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:26.315953 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3643,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:26.316573 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushMRSOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:26.351902 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushMRSOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1375,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2086,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:26.352871 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling LogGCOp(045194e7023c452f986e5c901c33864e): free 132118257 bytes of WAL
I20260812 06:16:26.353142 13334 log_reader.cc:385] T 045194e7023c452f986e5c901c33864e: removed 13 log segments from log reader
I20260812 06:16:26.353235 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000014 (ops 67-70)
I20260812 06:16:26.353291 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000015 (ops 71-75)
I20260812 06:16:26.353345 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000016 (ops 76-80)
I20260812 06:16:26.353386 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000017 (ops 81-84)
I20260812 06:16:26.353422 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000018 (ops 85-89)
I20260812 06:16:26.353461 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000019 (ops 90-94)
I20260812 06:16:26.353495 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000020 (ops 95-99)
I20260812 06:16:26.353530 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000021 (ops 100-104)
I20260812 06:16:26.353569 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000022 (ops 105-108)
I20260812 06:16:26.353607 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000023 (ops 109-113)
I20260812 06:16:26.353643 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000024 (ops 114-118)
I20260812 06:16:26.353669 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000025 (ops 119-123)
I20260812 06:16:26.353693 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000026 (ops 124-128)
I20260812 06:16:26.383118 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: LogGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:26.383639 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e): 482 bytes on disk
I20260812 06:16:26.384182 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.384915 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=3.181125
I20260812 06:16:26.409933 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.025s	user 0.012s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4562,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:26.410514 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:26.425897 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:26.426506 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:26.645673 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.219s	user 0.143s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938886,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":792,"lbm_read_time_us":16318,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38925,"lbm_writes_lt_1ms":743,"mutex_wait_us":128,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:16:26.649937 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:26.712896 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.063s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21757,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.713574 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:26.730724 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.731230 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:26.910676 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.179s	user 0.137s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1076,"lbm_read_time_us":11974,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33456,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:16:26.911347 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:26.970472 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.059s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22420,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.971093 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:26.983409 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.983934 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:27.171465 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.187s	user 0.122s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":15345,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":31426,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:16:27.172063 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:27.222287 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.050s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22686,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.222779 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:27.243959 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.021s	user 0.011s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.244624 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:27.420962 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.176s	user 0.122s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":11776,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29866,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:16:27.421700 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:27.474624 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.053s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23449,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.475360 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:27.500535 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.025s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.501386 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:27.679636 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.178s	user 0.125s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":14292,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28912,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:27.680246 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:27.736621 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.056s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25618,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.737215 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:27.758690 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.021s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.759351 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:27.916919 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.157s	user 0.125s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":10323,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31107,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:16:27.917800 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=14.095187
I20260812 06:16:27.972893 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24192,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.973459 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=2.188937
I20260812 06:16:27.985832 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.986383 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushMRSOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:28.022148 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushMRSOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2402,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:28.022953 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling LogGCOp(045194e7023c452f986e5c901c33864e): free 128867718 bytes of WAL
I20260812 06:16:28.023247 13334 log_reader.cc:385] T 045194e7023c452f986e5c901c33864e: removed 13 log segments from log reader
I20260812 06:16:28.023317 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000027 (ops 129-133)
I20260812 06:16:28.023363 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000028 (ops 134-138)
I20260812 06:16:28.023392 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000029 (ops 139-142)
I20260812 06:16:28.023418 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000030 (ops 143-147)
I20260812 06:16:28.023453 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000031 (ops 148-152)
I20260812 06:16:28.023483 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000032 (ops 153-157)
I20260812 06:16:28.023520 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000033 (ops 158-162)
I20260812 06:16:28.023558 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000034 (ops 163-166)
I20260812 06:16:28.023590 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000035 (ops 167-171)
I20260812 06:16:28.023618 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000036 (ops 172-176)
I20260812 06:16:28.023643 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000037 (ops 177-180)
I20260812 06:16:28.023669 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000038 (ops 181-185)
I20260812 06:16:28.023703 13334 log.cc:1079] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/045194e7023c452f986e5c901c33864e/wal-000000039 (ops 186-190)
I20260812 06:16:28.058524 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: LogGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.035s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:16:28.059134 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e): 493 bytes on disk
I20260812 06:16:28.059617 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: UndoDeltaBlockGCOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:28.060339 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=5.165500
I20260812 06:16:28.096980 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.036s	user 0.017s	sys 0.019s Metrics: {"bytes_written":6851278,"delete_count":0,"lbm_write_time_us":9835,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:16:28.097610 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:28.104111 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.006s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":1523,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:16:28.104643 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e): perf score=1.000000
I20260812 06:16:28.260372 13161 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.029s	user 1.853s	sys 0.143s
I20260812 06:16:28.325702 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: MajorDeltaCompactionOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.221s	user 0.114s	sys 0.106s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938716,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17602,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38067,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3500}
I20260812 06:16:28.326246 13446 maintenance_manager.cc:419] P 46c7997de3d04fa78e0b91a1fad082cb: Scheduling FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e): perf score=10.126437
I20260812 06:16:28.348917 13161 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.088s	user 0.003s	sys 0.000s
I20260812 06:16:28.349610 13161 tablet_server.cc:179] TabletServer@127.12.218.65:0 shutting down...
I20260812 06:16:28.359388 13334 maintenance_manager.cc:643] P 46c7997de3d04fa78e0b91a1fad082cb: FlushDeltaMemStoresOp(045194e7023c452f986e5c901c33864e) complete. Timing: real 0.033s	user 0.025s	sys 0.006s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14619,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:28.359951 13161 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:28.360388 13161 tablet_replica.cc:333] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb: stopping tablet replica
I20260812 06:16:28.360626 13161 raft_consensus.cc:2243] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:28.360920 13161 raft_consensus.cc:2272] T 045194e7023c452f986e5c901c33864e P 46c7997de3d04fa78e0b91a1fad082cb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:28.377274 13161 tablet_server.cc:196] TabletServer@127.12.218.65:0 shutdown complete.
I20260812 06:16:28.391518 13161 master.cc:562] Master@127.12.218.126:37701 shutting down...
I20260812 06:16:28.395299 13161 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:28.395489 13161 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:28.395568 13161 tablet_replica.cc:333] T 00000000000000000000000000000000 P ec04f2f902034e2cb524094e93efdb56: stopping tablet replica
I20260812 06:16:28.407837 13161 master.cc:584] Master@127.12.218.126:37701 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5601 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:28.512178 13161 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.218.126:33969
I20260812 06:16:28.512638 13161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:28.515126 13161 server_base.cc:1061] running on GCE node
W20260812 06:16:28.515198 13495 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:28.515199 13496 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:28.515357 13500 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:28.515612 13161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.515658 13161 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:28.515676 13161 hybrid_clock.cc:648] HybridClock initialized: now 1786515388515675 us; error 0 us; skew 500 ppm
I20260812 06:16:28.516650 13161 webserver.cc:533] Webserver started at http://127.12.218.126:41689/ using document root <none> and password file <none>
I20260812 06:16:28.516894 13161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.516947 13161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.517055 13161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.517488 13161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/master-0-root/instance:
uuid: "fdb339832c644d058f16987893a5740f"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-g170"
I20260812 06:16:28.519043 13161 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:28.520005 13506 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:28.520241 13161 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:28.520332 13161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/master-0-root
uuid: "fdb339832c644d058f16987893a5740f"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-g170"
I20260812 06:16:28.520423 13161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-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:28.529014 13161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.529361 13161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.533589 13161 rpc_server.cc:307] RPC server started. Bound to: 127.12.218.126:33969
I20260812 06:16:28.535238 13603 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.218.126:33969 every 8 connection(s)
I20260812 06:16:28.537135 13605 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:28.542181 13605 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f: Bootstrap starting.
I20260812 06:16:28.542940 13605 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.543977 13605 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f: No bootstrap required, opened a new log
I20260812 06:16:28.544348 13605 raft_consensus.cc:359] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fdb339832c644d058f16987893a5740f" member_type: VOTER }
I20260812 06:16:28.544433 13605 raft_consensus.cc:385] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.544456 13605 raft_consensus.cc:740] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fdb339832c644d058f16987893a5740f, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.544560 13605 consensus_queue.cc:260] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [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: "fdb339832c644d058f16987893a5740f" member_type: VOTER }
I20260812 06:16:28.544659 13605 raft_consensus.cc:399] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.544685 13605 raft_consensus.cc:493] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.544719 13605 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.545414 13605 raft_consensus.cc:515] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fdb339832c644d058f16987893a5740f" member_type: VOTER }
I20260812 06:16:28.545527 13605 leader_election.cc:304] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [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: fdb339832c644d058f16987893a5740f; no voters: 
I20260812 06:16:28.545680 13605 leader_election.cc:290] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.545877 13608 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.546118 13608 raft_consensus.cc:697] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 1 LEADER]: Becoming Leader. State: Replica: fdb339832c644d058f16987893a5740f, State: Running, Role: LEADER
I20260812 06:16:28.546186 13605 sys_catalog.cc:565] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:28.546284 13608 consensus_queue.cc:237] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [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: "fdb339832c644d058f16987893a5740f" member_type: VOTER }
I20260812 06:16:28.546780 13609 sys_catalog.cc:455] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fdb339832c644d058f16987893a5740f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fdb339832c644d058f16987893a5740f" member_type: VOTER } }
I20260812 06:16:28.546833 13612 sys_catalog.cc:455] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [sys.catalog]: SysCatalogTable state changed. Reason: New leader fdb339832c644d058f16987893a5740f. Latest consensus state: current_term: 1 leader_uuid: "fdb339832c644d058f16987893a5740f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fdb339832c644d058f16987893a5740f" member_type: VOTER } }
I20260812 06:16:28.546890 13609 sys_catalog.cc:458] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.546931 13612 sys_catalog.cc:458] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.547312 13622 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:28.548251 13622 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:28.548447 13161 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:28.550239 13622 catalog_manager.cc:1383] Generated new cluster ID: 8252ad5b241942c79e6c141b8eb9c521
I20260812 06:16:28.550290 13622 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:28.558787 13622 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:28.559346 13622 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:28.565444 13622 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f: Generated new TSK 0
I20260812 06:16:28.565615 13622 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:28.580992 13161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:28.583030 13637 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:28.583245 13641 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:28.583501 13648 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:28.583671 13161 server_base.cc:1061] running on GCE node
I20260812 06:16:28.583845 13161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.583881 13161 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:28.583896 13161 hybrid_clock.cc:648] HybridClock initialized: now 1786515388583897 us; error 0 us; skew 500 ppm
I20260812 06:16:28.584728 13161 webserver.cc:533] Webserver started at http://127.12.218.65:41663/ using document root <none> and password file <none>
I20260812 06:16:28.584933 13161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.584980 13161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.585098 13161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.585515 13161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/instance:
uuid: "f1907233ccc143b0bbabf4ab8ebd08d2"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-g170"
I20260812 06:16:28.587129 13161 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:28.588270 13655 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:28.588569 13161 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:28.588703 13161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root
uuid: "f1907233ccc143b0bbabf4ab8ebd08d2"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-g170"
I20260812 06:16:28.588824 13161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-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:28.593715 13161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.594022 13161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.594254 13161 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:28.594759 13161 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:28.594805 13161 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.594861 13161 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:28.594899 13161 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.599485 13161 rpc_server.cc:307] RPC server started. Bound to: 127.12.218.65:37823
I20260812 06:16:28.600666 13761 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.218.65:37823 every 8 connection(s)
I20260812 06:16:28.611536 13763 heartbeater.cc:344] Connected to a master server at 127.12.218.126:33969
I20260812 06:16:28.611646 13763 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:28.611901 13763 heartbeater.cc:507] Master 127.12.218.126:33969 requested a full tablet report, sending...
I20260812 06:16:28.612563 13541 ts_manager.cc:194] Registered new tserver with Master: f1907233ccc143b0bbabf4ab8ebd08d2 (127.12.218.65:37823)
I20260812 06:16:28.612900 13161 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012504014s
I20260812 06:16:28.613466 13541 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48326
I20260812 06:16:28.620927 13541 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48330:
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:28.630416 13702 tablet_service.cc:1511] Processing CreateTablet for tablet 67c1984c5ed646afb88941ace528cd4a (DEFAULT_TABLE table=heavy-update-compaction-test [id=4c1ae00e71b0465690a7d7a131ab2317]), partition=
I20260812 06:16:28.630666 13702 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 67c1984c5ed646afb88941ace528cd4a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:28.632920 13788 tablet_bootstrap.cc:492] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Bootstrap starting.
I20260812 06:16:28.633790 13788 tablet_bootstrap.cc:654] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.634874 13788 tablet_bootstrap.cc:492] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: No bootstrap required, opened a new log
I20260812 06:16:28.634970 13788 ts_tablet_manager.cc:1403] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:28.635454 13788 raft_consensus.cc:359] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f1907233ccc143b0bbabf4ab8ebd08d2" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 37823 } }
I20260812 06:16:28.635565 13788 raft_consensus.cc:385] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.635609 13788 raft_consensus.cc:740] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f1907233ccc143b0bbabf4ab8ebd08d2, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.635746 13788 consensus_queue.cc:260] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [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: "f1907233ccc143b0bbabf4ab8ebd08d2" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 37823 } }
I20260812 06:16:28.635823 13788 raft_consensus.cc:399] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.635893 13788 raft_consensus.cc:493] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.635951 13788 raft_consensus.cc:3060] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.636639 13788 raft_consensus.cc:515] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f1907233ccc143b0bbabf4ab8ebd08d2" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 37823 } }
I20260812 06:16:28.636809 13788 leader_election.cc:304] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [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: f1907233ccc143b0bbabf4ab8ebd08d2; no voters: 
I20260812 06:16:28.637032 13788 leader_election.cc:290] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.637156 13793 raft_consensus.cc:2804] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.637375 13788 ts_tablet_manager.cc:1434] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:28.637408 13793 raft_consensus.cc:697] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 1 LEADER]: Becoming Leader. State: Replica: f1907233ccc143b0bbabf4ab8ebd08d2, State: Running, Role: LEADER
I20260812 06:16:28.637416 13763 heartbeater.cc:499] Master 127.12.218.126:33969 was elected leader, sending a full tablet report...
I20260812 06:16:28.637604 13793 consensus_queue.cc:237] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [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: "f1907233ccc143b0bbabf4ab8ebd08d2" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 37823 } }
I20260812 06:16:28.638958 13541 catalog_manager.cc:5719] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 reported cstate change: term changed from 0 to 1, leader changed from <none> to f1907233ccc143b0bbabf4ab8ebd08d2 (127.12.218.65). New cstate: current_term: 1 leader_uuid: "f1907233ccc143b0bbabf4ab8ebd08d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f1907233ccc143b0bbabf4ab8ebd08d2" member_type: VOTER last_known_addr { host: "127.12.218.65" port: 37823 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:28.700047 13161 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.008s
I20260812 06:16:28.851233 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushMRSOp(67c1984c5ed646afb88941ace528cd4a): perf score=19.054940
I20260812 06:16:29.001327 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushMRSOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.150s	user 0.113s	sys 0.035s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":727,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40079,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:29.002228 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling LogGCOp(67c1984c5ed646afb88941ace528cd4a): free 20743880 bytes of WAL
I20260812 06:16:29.002523 13663 log_reader.cc:385] T 67c1984c5ed646afb88941ace528cd4a: removed 2 log segments from log reader
I20260812 06:16:29.002576 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000001 (ops 1-6)
I20260812 06:16:29.002610 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000002 (ops 7-11)
I20260812 06:16:29.007484 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: LogGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:29.007953 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:29.025220 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.025693 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:29.190600 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.165s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":13292,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28282,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":342,"threads_started":5,"update_count":2000}
I20260812 06:16:29.191287 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a): 16411394 bytes on disk
I20260812 06:16:29.191651 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.192052 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=11.118625
I20260812 06:16:29.228466 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15597,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:29.229023 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:29.239779 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:29.240368 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:29.394039 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.153s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1163,"lbm_read_time_us":12661,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24797,"lbm_writes_lt_1ms":443,"mutex_wait_us":385,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2000}
I20260812 06:16:29.394923 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=10.126437
I20260812 06:16:29.429736 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.035s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15442,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.430222 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:29.446154 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.446619 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:29.587494 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.141s	user 0.122s	sys 0.016s 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":1250,"lbm_read_time_us":10548,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25837,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:16:29.588109 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=10.126437
I20260812 06:16:29.641291 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.053s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20086,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.641816 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:29.655185 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.655699 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:29.792470 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.137s	user 0.124s	sys 0.012s 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":297,"lbm_read_time_us":11758,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26373,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2000}
I20260812 06:16:29.793205 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=10.126437
I20260812 06:16:29.834241 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.041s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16059,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.834748 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:29.846355 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.847014 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:29.976915 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.130s	user 0.106s	sys 0.023s 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":350,"lbm_read_time_us":11067,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23418,"lbm_writes_lt_1ms":443,"mutex_wait_us":18,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:16:29.977598 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=10.126437
I20260812 06:16:30.039978 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.062s	user 0.018s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16603,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.040438 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:30.051291 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.051673 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:30.210114 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.158s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":12066,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23707,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:16:30.210839 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=10.126437
I20260812 06:16:30.257901 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.258462 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:30.269975 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.270637 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushMRSOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:30.299610 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushMRSOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1506,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1556,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:30.300240 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling LogGCOp(67c1984c5ed646afb88941ace528cd4a): free 108535449 bytes of WAL
I20260812 06:16:30.300493 13663 log_reader.cc:385] T 67c1984c5ed646afb88941ace528cd4a: removed 11 log segments from log reader
I20260812 06:16:30.300556 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000003 (ops 12-16)
I20260812 06:16:30.300608 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000004 (ops 17-21)
I20260812 06:16:30.300644 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000005 (ops 22-26)
I20260812 06:16:30.300681 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000006 (ops 27-30)
I20260812 06:16:30.300719 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000007 (ops 31-35)
I20260812 06:16:30.300756 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000008 (ops 36-40)
I20260812 06:16:30.300814 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000009 (ops 41-44)
I20260812 06:16:30.300853 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000010 (ops 45-49)
I20260812 06:16:30.300890 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000011 (ops 50-54)
I20260812 06:16:30.300926 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000012 (ops 55-59)
I20260812 06:16:30.300963 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000013 (ops 60-64)
I20260812 06:16:30.326659 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: LogGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:16:30.327056 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a): 447 bytes on disk
I20260812 06:16:30.327512 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.328141 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:30.357437 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.029s	user 0.011s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.357918 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:30.368610 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.369117 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:30.598034 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.229s	user 0.166s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4861,"lbm_read_time_us":15678,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40681,"lbm_writes_lt_1ms":643,"mutex_wait_us":1343,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":120,"threads_started":1,"update_count":3000}
I20260812 06:16:30.598768 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:30.658155 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.059s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.658710 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:30.669685 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.670207 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:30.861542 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.191s	user 0.119s	sys 0.068s 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":601,"lbm_read_time_us":14458,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32099,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:30.862253 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:30.913436 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.051s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25108,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.913918 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:30.936072 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.022s	user 0.006s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.936882 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:31.137916 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.201s	user 0.144s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1235,"lbm_read_time_us":14778,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32712,"lbm_writes_lt_1ms":543,"mutex_wait_us":606,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:16:31.143067 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:31.209065 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.065s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27449,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.209715 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:31.228459 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.229065 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:31.426292 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.197s	user 0.138s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":791,"lbm_read_time_us":12727,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32015,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:16:31.427018 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:31.480391 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.053s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18307,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.481012 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:31.499089 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.499775 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:31.672394 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.172s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":13010,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36002,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:16:31.673131 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=11.118625
I20260812 06:16:31.718883 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.046s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22007,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:31.719372 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:31.738343 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.019s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3964,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.738782 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:31.749652 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.750236 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:31.911681 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.161s	user 0.121s	sys 0.033s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":532,"lbm_read_time_us":10090,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34679,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:16:31.912379 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=11.118625
I20260812 06:16:31.960434 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.048s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18577,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:16:31.961004 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:31.979357 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.979828 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:31.989583 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3655,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.990042 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushMRSOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:32.024744 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushMRSOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1221,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2062,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:32.025480 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling LogGCOp(67c1984c5ed646afb88941ace528cd4a): free 136275175 bytes of WAL
I20260812 06:16:32.025765 13663 log_reader.cc:385] T 67c1984c5ed646afb88941ace528cd4a: removed 13 log segments from log reader
I20260812 06:16:32.025826 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000014 (ops 65-69)
I20260812 06:16:32.025868 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000015 (ops 70-74)
I20260812 06:16:32.025900 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000016 (ops 75-79)
I20260812 06:16:32.025930 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000017 (ops 80-84)
I20260812 06:16:32.025954 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000018 (ops 85-89)
I20260812 06:16:32.025980 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000019 (ops 90-94)
I20260812 06:16:32.026005 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000020 (ops 95-99)
I20260812 06:16:32.026027 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000021 (ops 100-104)
I20260812 06:16:32.026049 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000022 (ops 105-108)
I20260812 06:16:32.026078 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000023 (ops 109-113)
I20260812 06:16:32.026108 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000024 (ops 114-118)
I20260812 06:16:32.026149 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000025 (ops 119-123)
I20260812 06:16:32.026186 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000026 (ops 124-128)
I20260812 06:16:32.059234 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: LogGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:16:32.059613 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a): 493 bytes on disk
I20260812 06:16:32.060117 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.060628 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=3.181125
I20260812 06:16:32.074899 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5394,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:32.075428 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:32.089568 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5351,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:32.090149 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:32.333504 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.243s	user 0.147s	sys 0.081s 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":936,"lbm_read_time_us":13356,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41254,"lbm_writes_lt_1ms":743,"mutex_wait_us":333,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:16:32.334235 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=18.063937
I20260812 06:16:32.410833 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.075s	user 0.046s	sys 0.027s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27144,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:32.411674 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:32.431097 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.431702 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:32.675267 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.243s	user 0.166s	sys 0.077s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":508,"lbm_read_time_us":18024,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38527,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":3000}
I20260812 06:16:32.676090 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:32.723973 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.048s	user 0.021s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21008,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.724825 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:32.740480 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.741120 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:32.926247 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.185s	user 0.116s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":699,"lbm_read_time_us":13764,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30857,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":100352,"update_count":2500}
I20260812 06:16:32.926774 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:32.987820 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.061s	user 0.039s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21002,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.988405 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:33.005329 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.006193 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:33.200469 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.194s	user 0.138s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":343,"lbm_read_time_us":12243,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32899,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:16:33.201161 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=14.095187
I20260812 06:16:33.273355 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.072s	user 0.036s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.274003 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:33.290628 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.291070 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:33.480753 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.189s	user 0.134s	sys 0.052s 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":572,"lbm_read_time_us":13933,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30955,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:33.481348 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=11.118625
I20260812 06:16:33.533728 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.052s	user 0.037s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":23692,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:33.534304 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:33.554749 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.020s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.555253 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:33.565136 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3815,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.565598 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushMRSOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:33.609153 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushMRSOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.043s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1179,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1510,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:33.609834 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling LogGCOp(67c1984c5ed646afb88941ace528cd4a): free 120553636 bytes of WAL
I20260812 06:16:33.610075 13663 log_reader.cc:385] T 67c1984c5ed646afb88941ace528cd4a: removed 12 log segments from log reader
I20260812 06:16:33.610140 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000027 (ops 129-133)
I20260812 06:16:33.610205 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000028 (ops 134-138)
I20260812 06:16:33.610262 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000029 (ops 139-143)
I20260812 06:16:33.610306 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000030 (ops 144-148)
I20260812 06:16:33.610343 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000031 (ops 149-152)
I20260812 06:16:33.610383 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000032 (ops 153-157)
I20260812 06:16:33.610422 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000033 (ops 158-162)
I20260812 06:16:33.610460 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000034 (ops 163-167)
I20260812 06:16:33.610498 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000035 (ops 168-172)
I20260812 06:16:33.610538 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000036 (ops 173-177)
I20260812 06:16:33.610575 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000037 (ops 178-182)
I20260812 06:16:33.610613 13663 log.cc:1079] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: Deleting log segment in path: /tmp/dist-test-task6OTYkV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382888524-13161-0/minicluster-data/ts-0-root/wals/67c1984c5ed646afb88941ace528cd4a/wal-000000038 (ops 183-186)
I20260812 06:16:33.639124 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: LogGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.029s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:16:33.639742 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a): 447 bytes on disk
I20260812 06:16:33.640364 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: UndoDeltaBlockGCOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.641044 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=3.181125
I20260812 06:16:33.654613 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4923146,"delete_count":0,"lbm_write_time_us":5494,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 06:16:33.655030 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:33.663864 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":3254,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:16:33.664305 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:33.901472 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.237s	user 0.151s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979844,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":404,"dirs.run_cpu_time_us":886,"dirs.run_wall_time_us":4880,"lbm_read_time_us":15850,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40055,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":3500}
I20260812 06:16:33.903977 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=15.087375
I20260812 06:16:33.954906 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.051s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":21950,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:33.955619 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:33.986738 13161 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.287s	user 1.909s	sys 0.242s
I20260812 06:16:33.988806 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.033s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6627,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":450}
I20260812 06:16:33.989382 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a): perf score=2.188937
I20260812 06:16:34.001876 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: FlushDeltaMemStoresOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.002451 13769 maintenance_manager.cc:419] P f1907233ccc143b0bbabf4ab8ebd08d2: Scheduling MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a): perf score=1.000000
I20260812 06:16:34.092149 13161 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.105s	user 0.001s	sys 0.000s
I20260812 06:16:34.092749 13161 tablet_server.cc:179] TabletServer@127.12.218.65:0 shutting down...
I20260812 06:16:34.190234 13663 maintenance_manager.cc:643] P f1907233ccc143b0bbabf4ab8ebd08d2: MajorDeltaCompactionOp(67c1984c5ed646afb88941ace528cd4a) complete. Timing: real 0.188s	user 0.127s	sys 0.060s Metrics: {"cfile_cache_hit":172,"cfile_cache_hit_bytes":6978656,"cfile_cache_miss":461,"cfile_cache_miss_bytes":21898551,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":793,"lbm_read_time_us":13337,"lbm_reads_lt_1ms":493,"lbm_write_time_us":35358,"lbm_writes_lt_1ms":643,"mutex_wait_us":333,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":715776,"update_count":3000}
I20260812 06:16:34.190961 13161 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.191186 13161 tablet_replica.cc:333] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2: stopping tablet replica
I20260812 06:16:34.191375 13161 raft_consensus.cc:2243] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.191567 13161 raft_consensus.cc:2272] T 67c1984c5ed646afb88941ace528cd4a P f1907233ccc143b0bbabf4ab8ebd08d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.196290 13161 tablet_server.cc:196] TabletServer@127.12.218.65:0 shutdown complete.
I20260812 06:16:34.245442 13161 master.cc:562] Master@127.12.218.126:33969 shutting down...
I20260812 06:16:34.248817 13161 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.248991 13161 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.249042 13161 tablet_replica.cc:333] T 00000000000000000000000000000000 P fdb339832c644d058f16987893a5740f: stopping tablet replica
I20260812 06:16:34.261731 13161 master.cc:584] Master@127.12.218.126:33969 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5858 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11460 ms total)

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