[==========] 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:18:59.987516 13542 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.57.190:42073
I20260812 06:18:59.988710 13542 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:18:59.989508 13542 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.995836 13547 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:18:59.996001 13542 server_base.cc:1061] running on GCE node
W20260812 06:18:59.996148 13550 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.996157 13548 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:18:59.996667 13542 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.996776 13542 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:18:59.996822 13542 hybrid_clock.cc:648] HybridClock initialized: now 1786515539996820 us; error 0 us; skew 500 ppm
I20260812 06:18:59.998529 13542 webserver.cc:533] Webserver started at http://127.13.57.190:46439/ using document root <none> and password file <none>
I20260812 06:18:59.999061 13542 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.999121 13542 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.999352 13542 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:00.001015 13542 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/master-0-root/instance:
uuid: "40e61e5eabbc4b47a362765b5c8a1da6"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-vq2q"
I20260812 06:19:00.004534 13542 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:00.006610 13557 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.007639 13542 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:00.007761 13542 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/master-0-root
uuid: "40e61e5eabbc4b47a362765b5c8a1da6"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-vq2q"
I20260812 06:19:00.007848 13542 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:00.032305 13542 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.033020 13542 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:00.033209 13542 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.040689 13542 rpc_server.cc:307] RPC server started. Bound to: 127.13.57.190:42073
I20260812 06:19:00.040696 13623 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.57.190:42073 every 8 connection(s)
I20260812 06:19:00.043051 13625 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.048954 13625 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: Bootstrap starting.
I20260812 06:19:00.051417 13625 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.052309 13625 log.cc:826] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:00.054064 13625 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: No bootstrap required, opened a new log
I20260812 06:19:00.056808 13625 raft_consensus.cc:359] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e61e5eabbc4b47a362765b5c8a1da6" member_type: VOTER }
I20260812 06:19:00.056972 13625 raft_consensus.cc:385] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.057034 13625 raft_consensus.cc:740] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 40e61e5eabbc4b47a362765b5c8a1da6, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.057700 13625 consensus_queue.cc:260] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [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: "40e61e5eabbc4b47a362765b5c8a1da6" member_type: VOTER }
I20260812 06:19:00.057848 13625 raft_consensus.cc:399] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.057916 13625 raft_consensus.cc:493] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.058035 13625 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.058794 13625 raft_consensus.cc:515] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e61e5eabbc4b47a362765b5c8a1da6" member_type: VOTER }
I20260812 06:19:00.059221 13625 leader_election.cc:304] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [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: 40e61e5eabbc4b47a362765b5c8a1da6; no voters: 
I20260812 06:19:00.059546 13625 leader_election.cc:290] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.059686 13628 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.059926 13628 raft_consensus.cc:697] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 1 LEADER]: Becoming Leader. State: Replica: 40e61e5eabbc4b47a362765b5c8a1da6, State: Running, Role: LEADER
I20260812 06:19:00.060287 13628 consensus_queue.cc:237] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [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: "40e61e5eabbc4b47a362765b5c8a1da6" member_type: VOTER }
I20260812 06:19:00.060510 13625 sys_catalog.cc:565] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:00.062214 13629 sys_catalog.cc:455] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "40e61e5eabbc4b47a362765b5c8a1da6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e61e5eabbc4b47a362765b5c8a1da6" member_type: VOTER } }
I20260812 06:19:00.062335 13629 sys_catalog.cc:458] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.062587 13630 sys_catalog.cc:455] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 40e61e5eabbc4b47a362765b5c8a1da6. Latest consensus state: current_term: 1 leader_uuid: "40e61e5eabbc4b47a362765b5c8a1da6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e61e5eabbc4b47a362765b5c8a1da6" member_type: VOTER } }
I20260812 06:19:00.062657 13630 sys_catalog.cc:458] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.062717 13542 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:00.064669 13646 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:00.064733 13646 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:00.064810 13645 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:00.065613 13645 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:00.069882 13645 catalog_manager.cc:1383] Generated new cluster ID: 95eecaa93e6e481daac20e83fffbfc41
I20260812 06:19:00.069942 13645 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:00.081032 13645 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:00.081858 13645 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:00.087581 13645 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: Generated new TSK 0
I20260812 06:19:00.088164 13645 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:00.095295 13542 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:00.098114 13650 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:00.098248 13654 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:00.098282 13652 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:00.098448 13542 server_base.cc:1061] running on GCE node
I20260812 06:19:00.098670 13542 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:00.098714 13542 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:00.098728 13542 hybrid_clock.cc:648] HybridClock initialized: now 1786515540098728 us; error 0 us; skew 500 ppm
I20260812 06:19:00.099597 13542 webserver.cc:533] Webserver started at http://127.13.57.129:43351/ using document root <none> and password file <none>
I20260812 06:19:00.099762 13542 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:00.099820 13542 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:00.099921 13542 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:00.100292 13542 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/instance:
uuid: "07b30c9d7ba04ee4aa4d3a10dc54d2ad"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-vq2q"
I20260812 06:19:00.101800 13542 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:00.102766 13659 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.103034 13542 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:00.103106 13542 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root
uuid: "07b30c9d7ba04ee4aa4d3a10dc54d2ad"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-vq2q"
I20260812 06:19:00.103176 13542 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:00.111092 13542 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.111913 13542 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.112407 13542 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:00.113324 13542 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:00.113379 13542 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.113428 13542 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:00.113459 13542 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.119539 13542 rpc_server.cc:307] RPC server started. Bound to: 127.13.57.129:43949
I20260812 06:19:00.119585 13737 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.57.129:43949 every 8 connection(s)
I20260812 06:19:00.129674 13738 heartbeater.cc:344] Connected to a master server at 127.13.57.190:42073
I20260812 06:19:00.129908 13738 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:00.130371 13738 heartbeater.cc:507] Master 127.13.57.190:42073 requested a full tablet report, sending...
I20260812 06:19:00.132045 13577 ts_manager.cc:194] Registered new tserver with Master: 07b30c9d7ba04ee4aa4d3a10dc54d2ad (127.13.57.129:43949)
I20260812 06:19:00.132362 13542 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01220796s
I20260812 06:19:00.133268 13577 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57414
I20260812 06:19:00.141536 13577 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57430:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:00.155292 13691 tablet_service.cc:1511] Processing CreateTablet for tablet ee45d934a6d442128634eab9c6b11df8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0c33d1b98a7c44f5ba84dc194557cb94]), partition=
I20260812 06:19:00.155730 13691 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ee45d934a6d442128634eab9c6b11df8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.158128 13751 tablet_bootstrap.cc:492] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Bootstrap starting.
I20260812 06:19:00.159129 13751 tablet_bootstrap.cc:654] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.160159 13751 tablet_bootstrap.cc:492] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: No bootstrap required, opened a new log
I20260812 06:19:00.160243 13751 ts_tablet_manager.cc:1403] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:00.160648 13751 raft_consensus.cc:359] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07b30c9d7ba04ee4aa4d3a10dc54d2ad" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 43949 } }
I20260812 06:19:00.160754 13751 raft_consensus.cc:385] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.160787 13751 raft_consensus.cc:740] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 07b30c9d7ba04ee4aa4d3a10dc54d2ad, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.160915 13751 consensus_queue.cc:260] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [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: "07b30c9d7ba04ee4aa4d3a10dc54d2ad" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 43949 } }
I20260812 06:19:00.160991 13751 raft_consensus.cc:399] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.161026 13751 raft_consensus.cc:493] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.161075 13751 raft_consensus.cc:3060] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.161983 13751 raft_consensus.cc:515] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07b30c9d7ba04ee4aa4d3a10dc54d2ad" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 43949 } }
I20260812 06:19:00.162161 13751 leader_election.cc:304] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [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: 07b30c9d7ba04ee4aa4d3a10dc54d2ad; no voters: 
I20260812 06:19:00.162398 13751 leader_election.cc:290] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.162670 13754 raft_consensus.cc:2804] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.162894 13751 ts_tablet_manager.cc:1434] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:00.163098 13738 heartbeater.cc:499] Master 127.13.57.190:42073 was elected leader, sending a full tablet report...
I20260812 06:19:00.162905 13754 raft_consensus.cc:697] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 1 LEADER]: Becoming Leader. State: Replica: 07b30c9d7ba04ee4aa4d3a10dc54d2ad, State: Running, Role: LEADER
I20260812 06:19:00.163473 13754 consensus_queue.cc:237] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [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: "07b30c9d7ba04ee4aa4d3a10dc54d2ad" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 43949 } }
I20260812 06:19:00.166139 13577 catalog_manager.cc:5719] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad reported cstate change: term changed from 0 to 1, leader changed from <none> to 07b30c9d7ba04ee4aa4d3a10dc54d2ad (127.13.57.129). New cstate: current_term: 1 leader_uuid: "07b30c9d7ba04ee4aa4d3a10dc54d2ad" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07b30c9d7ba04ee4aa4d3a10dc54d2ad" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 43949 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:00.232268 13542 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.022s	sys 0.005s
I20260812 06:19:00.370675 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushMRSOp(ee45d934a6d442128634eab9c6b11df8): perf score=19.054940
I20260812 06:19:00.538573 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushMRSOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.167s	user 0.144s	sys 0.020s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":293,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":908,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40198,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":161,"threads_started":1,"update_count":1500}
I20260812 06:19:00.539753 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling LogGCOp(ee45d934a6d442128634eab9c6b11df8): free 20743880 bytes of WAL
I20260812 06:19:00.540066 13664 log_reader.cc:385] T ee45d934a6d442128634eab9c6b11df8: removed 2 log segments from log reader
I20260812 06:19:00.540124 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000001 (ops 1-6)
I20260812 06:19:00.540189 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000002 (ops 7-11)
I20260812 06:19:00.545239 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: LogGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:00.545713 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:00.560920 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.015s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.561474 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:00.708998 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.147s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":681,"lbm_read_time_us":9495,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23364,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":283,"threads_started":5,"update_count":2000}
I20260812 06:19:00.709537 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling UndoDeltaBlockGCOp(ee45d934a6d442128634eab9c6b11df8): 16411392 bytes on disk
I20260812 06:19:00.710165 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: UndoDeltaBlockGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.710784 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:00.748517 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.038s	user 0.008s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13030,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.749073 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:00.758893 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.759397 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:00.888810 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.129s	user 0.101s	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":934,"lbm_read_time_us":9051,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21552,"lbm_writes_lt_1ms":443,"mutex_wait_us":306,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:19:00.889320 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:00.927762 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.038s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.928339 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:00.938539 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.939152 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:01.048624 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.109s	user 0.102s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":452,"lbm_read_time_us":7678,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20039,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:01.049216 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:01.091881 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.042s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307487,"delete_count":0,"lbm_write_time_us":14343,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.092404 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:01.102473 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.102875 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:01.235538 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.133s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":9569,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20513,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2000}
I20260812 06:19:01.236035 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:01.280418 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.044s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12605,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.280980 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:01.296590 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.297165 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:01.415361 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.118s	user 0.081s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":526,"lbm_read_time_us":7470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21869,"lbm_writes_lt_1ms":443,"mutex_wait_us":224,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:01.415854 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:01.449985 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.034s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12662,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.450451 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:01.460799 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.461470 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:01.571606 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.110s	user 0.087s	sys 0.021s 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":264,"lbm_read_time_us":7977,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20256,"lbm_writes_lt_1ms":443,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:01.572119 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:01.625128 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.053s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15839,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.625699 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:01.636075 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.636608 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushMRSOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:01.677361 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushMRSOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.041s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1260,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1650,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:01.678319 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling LogGCOp(ee45d934a6d442128634eab9c6b11df8): free 112692367 bytes of WAL
I20260812 06:19:01.678565 13664 log_reader.cc:385] T ee45d934a6d442128634eab9c6b11df8: removed 11 log segments from log reader
I20260812 06:19:01.678628 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000003 (ops 12-16)
I20260812 06:19:01.678673 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000004 (ops 17-21)
I20260812 06:19:01.678704 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000005 (ops 22-26)
I20260812 06:19:01.678736 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000006 (ops 27-31)
I20260812 06:19:01.678766 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000007 (ops 32-36)
I20260812 06:19:01.678793 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000008 (ops 37-41)
I20260812 06:19:01.678817 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000009 (ops 42-46)
I20260812 06:19:01.678843 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000010 (ops 47-51)
I20260812 06:19:01.678884 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000011 (ops 52-56)
I20260812 06:19:01.678915 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000012 (ops 57-61)
I20260812 06:19:01.678939 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000013 (ops 62-66)
I20260812 06:19:01.701643 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: LogGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:01.702083 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling UndoDeltaBlockGCOp(ee45d934a6d442128634eab9c6b11df8): 447 bytes on disk
I20260812 06:19:01.702669 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: UndoDeltaBlockGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.703228 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:01.726914 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.727368 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:01.737838 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.738336 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:01.931569 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.193s	user 0.131s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1097,"lbm_read_time_us":11866,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36244,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":134,"threads_started":1,"update_count":3000}
I20260812 06:19:01.932125 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=14.095187
I20260812 06:19:01.982947 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.051s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.983413 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:02.127892 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.144s	user 0.089s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":788,"lbm_read_time_us":9737,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22379,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:02.128388 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=11.118625
I20260812 06:19:02.164876 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.036s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15236,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.165716 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:02.179901 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5190,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.180349 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:02.299290 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.119s	user 0.095s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":348,"lbm_read_time_us":7258,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22755,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:02.299798 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:02.340468 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.040s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17624,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.341209 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:02.353556 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.354045 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:02.473474 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.119s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":8638,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22046,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:02.473994 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:02.517197 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.043s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19482,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.517700 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:02.527619 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.528221 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:02.645617 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.117s	user 0.088s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1037,"lbm_read_time_us":9418,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20093,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:19:02.648288 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:02.691422 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.043s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13502,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.692056 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:02.707425 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.707983 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:02.851320 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.143s	user 0.097s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":9958,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23863,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:19:02.851934 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:02.887814 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.036s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13339,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.888309 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:02.903776 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.904589 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:03.026117 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.121s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":8035,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22504,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:03.026849 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=10.126437
I20260812 06:19:03.067375 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16575,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.067914 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:03.078049 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.078620 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushMRSOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:03.111778 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushMRSOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.033s	user 0.028s	sys 0.002s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1309,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1583,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":1280}
I20260812 06:19:03.112633 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling LogGCOp(ee45d934a6d442128634eab9c6b11df8): free 120100325 bytes of WAL
I20260812 06:19:03.112893 13664 log_reader.cc:385] T ee45d934a6d442128634eab9c6b11df8: removed 12 log segments from log reader
I20260812 06:19:03.112953 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000014 (ops 67-70)
I20260812 06:19:03.112990 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000015 (ops 71-75)
I20260812 06:19:03.113058 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000016 (ops 76-80)
I20260812 06:19:03.113091 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000017 (ops 81-84)
I20260812 06:19:03.113111 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000018 (ops 85-89)
I20260812 06:19:03.113159 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000019 (ops 90-94)
I20260812 06:19:03.113231 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000020 (ops 95-98)
I20260812 06:19:03.113265 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000021 (ops 99-103)
I20260812 06:19:03.113328 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000022 (ops 104-108)
I20260812 06:19:03.113359 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000023 (ops 109-113)
I20260812 06:19:03.113408 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000024 (ops 114-118)
I20260812 06:19:03.113438 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000025 (ops 119-123)
I20260812 06:19:03.135936 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: LogGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:03.136405 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=3.181125
I20260812 06:19:03.148423 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:03.148909 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:03.162566 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4778,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.163034 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:03.330817 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.168s	user 0.111s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":485,"lbm_read_time_us":10553,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31209,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:19:03.331396 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=14.095187
I20260812 06:19:03.375090 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.043s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16210,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.375679 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling UndoDeltaBlockGCOp(ee45d934a6d442128634eab9c6b11df8): 472 bytes on disk
I20260812 06:19:03.376099 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: UndoDeltaBlockGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.376765 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:03.389328 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.389954 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:03.532378 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.142s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":151,"lbm_read_time_us":11486,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24982,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:03.533054 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=11.118625
I20260812 06:19:03.575330 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.042s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20225,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:03.575870 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:03.598923 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.023s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3466,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.599496 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:03.614080 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.014s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.614578 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:03.781853 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.167s	user 0.105s	sys 0.058s 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":484,"lbm_read_time_us":12042,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27071,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:03.782814 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=12.110812
I20260812 06:19:03.822876 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":17039,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:19:03.823933 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.196750
I20260812 06:19:03.836524 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":2926,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:03.837133 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:03.996999 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.160s	user 0.106s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672248,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1044,"lbm_read_time_us":10504,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25592,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.997634 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=14.095187
I20260812 06:19:04.048977 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22793,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.049588 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:04.068066 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.018s	user 0.000s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.068737 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:04.248660 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.180s	user 0.116s	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":467,"lbm_read_time_us":10876,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27371,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":44288,"update_count":2500}
I20260812 06:19:04.249300 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=14.095187
I20260812 06:19:04.300737 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.051s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22245,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.301342 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:04.314742 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.315475 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:04.478153 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.163s	user 0.114s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":943,"lbm_read_time_us":10984,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24404,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:19:04.478636 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=14.095187
I20260812 06:19:04.524940 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.046s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":17814,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.525578 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:04.536288 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3900,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.536877 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushMRSOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:04.565380 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushMRSOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.028s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1358,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1473,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":768}
I20260812 06:19:04.566198 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling LogGCOp(ee45d934a6d442128634eab9c6b11df8): free 133024631 bytes of WAL
I20260812 06:19:04.566473 13664 log_reader.cc:385] T ee45d934a6d442128634eab9c6b11df8: removed 13 log segments from log reader
I20260812 06:19:04.566521 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000026 (ops 124-128)
I20260812 06:19:04.566561 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000027 (ops 129-133)
I20260812 06:19:04.566593 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000028 (ops 134-138)
I20260812 06:19:04.566624 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000029 (ops 139-143)
I20260812 06:19:04.566655 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000030 (ops 144-148)
I20260812 06:19:04.566684 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000031 (ops 149-153)
I20260812 06:19:04.566716 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000032 (ops 154-158)
I20260812 06:19:04.566746 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000033 (ops 159-162)
I20260812 06:19:04.566776 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000034 (ops 163-167)
I20260812 06:19:04.566805 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000035 (ops 168-172)
I20260812 06:19:04.566834 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000036 (ops 173-177)
I20260812 06:19:04.566864 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000037 (ops 178-182)
I20260812 06:19:04.566886 13664 log.cc:1079] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/ee45d934a6d442128634eab9c6b11df8/wal-000000038 (ops 183-187)
I20260812 06:19:04.591390 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: LogGCOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:04.591928 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=3.181125
I20260812 06:19:04.613158 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6694,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.613641 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:04.627813 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5148,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.628438 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:04.825886 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.197s	user 0.145s	sys 0.052s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":263,"lbm_read_time_us":14577,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33090,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":103,"threads_started":1,"update_count":3500}
I20260812 06:19:04.828557 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=14.095187
I20260812 06:19:04.884588 13542 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.652s	user 1.722s	sys 0.130s
I20260812 06:19:04.887732 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.059s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22479,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.888233 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8): perf score=2.188937
I20260812 06:19:04.897794 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: FlushDeltaMemStoresOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.898231 13739 maintenance_manager.cc:419] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: Scheduling MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8): perf score=1.000000
I20260812 06:19:04.950449 13542 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.003s	sys 0.000s
I20260812 06:19:04.951109 13542 tablet_server.cc:179] TabletServer@127.13.57.129:0 shutting down...
I20260812 06:19:05.022434 13664 maintenance_manager.cc:643] P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: MajorDeltaCompactionOp(ee45d934a6d442128634eab9c6b11df8) complete. Timing: real 0.124s	user 0.080s	sys 0.044s Metrics: {"cfile_cache_hit":233,"cfile_cache_hit_bytes":9519917,"cfile_cache_miss":299,"cfile_cache_miss_bytes":15254769,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1060,"lbm_read_time_us":6774,"lbm_reads_lt_1ms":331,"lbm_write_time_us":22272,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:05.023089 13542 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:05.023526 13542 tablet_replica.cc:333] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad: stopping tablet replica
I20260812 06:19:05.023756 13542 raft_consensus.cc:2243] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.023977 13542 raft_consensus.cc:2272] T ee45d934a6d442128634eab9c6b11df8 P 07b30c9d7ba04ee4aa4d3a10dc54d2ad [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.039291 13542 tablet_server.cc:196] TabletServer@127.13.57.129:0 shutdown complete.
I20260812 06:19:05.068073 13542 master.cc:562] Master@127.13.57.190:42073 shutting down...
I20260812 06:19:05.071343 13542 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.071521 13542 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.071579 13542 tablet_replica.cc:333] T 00000000000000000000000000000000 P 40e61e5eabbc4b47a362765b5c8a1da6: stopping tablet replica
I20260812 06:19:05.083901 13542 master.cc:584] Master@127.13.57.190:42073 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5169 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:05.167513 13542 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.57.190:43183
I20260812 06:19:05.167903 13542 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.169855 13775 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:05.169924 13778 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:05.170007 13776 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:05.170059 13542 server_base.cc:1061] running on GCE node
I20260812 06:19:05.170271 13542 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.170311 13542 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:05.170325 13542 hybrid_clock.cc:648] HybridClock initialized: now 1786515545170325 us; error 0 us; skew 500 ppm
I20260812 06:19:05.171175 13542 webserver.cc:533] Webserver started at http://127.13.57.190:36695/ using document root <none> and password file <none>
I20260812 06:19:05.171336 13542 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.171393 13542 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.171474 13542 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.171855 13542 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/master-0-root/instance:
uuid: "4cecc269c2064b10b92079167992f573"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-vq2q"
I20260812 06:19:05.173521 13542 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:05.174515 13784 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.174737 13542 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:05.174809 13542 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/master-0-root
uuid: "4cecc269c2064b10b92079167992f573"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-vq2q"
I20260812 06:19:05.174887 13542 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:05.183777 13542 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.184108 13542 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.188243 13542 rpc_server.cc:307] RPC server started. Bound to: 127.13.57.190:43183
I20260812 06:19:05.190850 13845 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.57.190:43183 every 8 connection(s)
I20260812 06:19:05.191407 13847 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:05.193344 13847 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573: Bootstrap starting.
I20260812 06:19:05.194167 13847 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.195127 13847 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573: No bootstrap required, opened a new log
I20260812 06:19:05.195489 13847 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4cecc269c2064b10b92079167992f573" member_type: VOTER }
I20260812 06:19:05.195573 13847 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.195598 13847 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4cecc269c2064b10b92079167992f573, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.195716 13847 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [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: "4cecc269c2064b10b92079167992f573" member_type: VOTER }
I20260812 06:19:05.195801 13847 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.195837 13847 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.195869 13847 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.196655 13847 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4cecc269c2064b10b92079167992f573" member_type: VOTER }
I20260812 06:19:05.196812 13847 leader_election.cc:304] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [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: 4cecc269c2064b10b92079167992f573; no voters: 
I20260812 06:19:05.196972 13847 leader_election.cc:290] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.197108 13850 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.197307 13850 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 1 LEADER]: Becoming Leader. State: Replica: 4cecc269c2064b10b92079167992f573, State: Running, Role: LEADER
I20260812 06:19:05.197413 13847 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:05.197451 13850 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [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: "4cecc269c2064b10b92079167992f573" member_type: VOTER }
I20260812 06:19:05.197880 13851 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4cecc269c2064b10b92079167992f573" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4cecc269c2064b10b92079167992f573" member_type: VOTER } }
I20260812 06:19:05.197908 13852 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4cecc269c2064b10b92079167992f573. Latest consensus state: current_term: 1 leader_uuid: "4cecc269c2064b10b92079167992f573" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4cecc269c2064b10b92079167992f573" member_type: VOTER } }
I20260812 06:19:05.197970 13851 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.197991 13852 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.198205 13855 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:05.199049 13855 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:05.199267 13542 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:05.200857 13855 catalog_manager.cc:1383] Generated new cluster ID: 62aa3945a3b64eaeb93e01e0d77755e0
I20260812 06:19:05.200914 13855 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:05.207675 13855 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:05.208184 13855 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:05.212987 13855 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573: Generated new TSK 0
I20260812 06:19:05.213132 13855 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:05.215384 13542 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.217132 13874 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:05.217258 13873 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:05.217355 13876 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:05.217429 13542 server_base.cc:1061] running on GCE node
I20260812 06:19:05.217597 13542 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.217633 13542 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:05.217656 13542 hybrid_clock.cc:648] HybridClock initialized: now 1786515545217656 us; error 0 us; skew 500 ppm
I20260812 06:19:05.218502 13542 webserver.cc:533] Webserver started at http://127.13.57.129:32783/ using document root <none> and password file <none>
I20260812 06:19:05.218658 13542 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.218708 13542 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.218782 13542 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.219172 13542 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/instance:
uuid: "a1af48db3c8d48e1a510fda78bf58586"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-vq2q"
I20260812 06:19:05.220544 13542 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:05.221462 13882 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.221663 13542 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:05.221730 13542 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root
uuid: "a1af48db3c8d48e1a510fda78bf58586"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-vq2q"
I20260812 06:19:05.221799 13542 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:05.240054 13542 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.240489 13542 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.240810 13542 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:05.241346 13542 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:05.241391 13542 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.241439 13542 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:05.241467 13542 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.245500 13542 rpc_server.cc:307] RPC server started. Bound to: 127.13.57.129:35497
I20260812 06:19:05.245559 13962 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.57.129:35497 every 8 connection(s)
I20260812 06:19:05.253487 13963 heartbeater.cc:344] Connected to a master server at 127.13.57.190:43183
I20260812 06:19:05.253608 13963 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:05.253845 13963 heartbeater.cc:507] Master 127.13.57.190:43183 requested a full tablet report, sending...
I20260812 06:19:05.254606 13806 ts_manager.cc:194] Registered new tserver with Master: a1af48db3c8d48e1a510fda78bf58586 (127.13.57.129:35497)
I20260812 06:19:05.254801 13542 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008855005s
I20260812 06:19:05.255419 13806 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48832
I20260812 06:19:05.261545 13806 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48836:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:05.270103 13920 tablet_service.cc:1511] Processing CreateTablet for tablet 7da15c234f0b4e67823f676bcdfd74fd (DEFAULT_TABLE table=heavy-update-compaction-test [id=ec476eecf22c43968d4909af7931f65c]), partition=
I20260812 06:19:05.270391 13920 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7da15c234f0b4e67823f676bcdfd74fd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:05.272488 13977 tablet_bootstrap.cc:492] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Bootstrap starting.
I20260812 06:19:05.273393 13977 tablet_bootstrap.cc:654] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.274451 13977 tablet_bootstrap.cc:492] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: No bootstrap required, opened a new log
I20260812 06:19:05.274534 13977 ts_tablet_manager.cc:1403] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:05.274945 13977 raft_consensus.cc:359] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1af48db3c8d48e1a510fda78bf58586" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 35497 } }
I20260812 06:19:05.275064 13977 raft_consensus.cc:385] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.275103 13977 raft_consensus.cc:740] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a1af48db3c8d48e1a510fda78bf58586, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.275238 13977 consensus_queue.cc:260] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [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: "a1af48db3c8d48e1a510fda78bf58586" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 35497 } }
I20260812 06:19:05.275333 13977 raft_consensus.cc:399] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.275386 13977 raft_consensus.cc:493] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.275444 13977 raft_consensus.cc:3060] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.276283 13977 raft_consensus.cc:515] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1af48db3c8d48e1a510fda78bf58586" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 35497 } }
I20260812 06:19:05.276420 13977 leader_election.cc:304] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [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: a1af48db3c8d48e1a510fda78bf58586; no voters: 
I20260812 06:19:05.276616 13977 leader_election.cc:290] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.276746 13979 raft_consensus.cc:2804] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.276965 13977 ts_tablet_manager.cc:1434] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:05.276980 13979 raft_consensus.cc:697] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 1 LEADER]: Becoming Leader. State: Replica: a1af48db3c8d48e1a510fda78bf58586, State: Running, Role: LEADER
I20260812 06:19:05.277032 13963 heartbeater.cc:499] Master 127.13.57.190:43183 was elected leader, sending a full tablet report...
I20260812 06:19:05.277204 13979 consensus_queue.cc:237] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [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: "a1af48db3c8d48e1a510fda78bf58586" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 35497 } }
I20260812 06:19:05.278510 13806 catalog_manager.cc:5719] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 reported cstate change: term changed from 0 to 1, leader changed from <none> to a1af48db3c8d48e1a510fda78bf58586 (127.13.57.129). New cstate: current_term: 1 leader_uuid: "a1af48db3c8d48e1a510fda78bf58586" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1af48db3c8d48e1a510fda78bf58586" member_type: VOTER last_known_addr { host: "127.13.57.129" port: 35497 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:05.338143 13542 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.010s	sys 0.012s
I20260812 06:19:05.496745 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=22.031503
I20260812 06:19:05.658536 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.161s	user 0.124s	sys 0.031s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":818,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39946,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:05.659314 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling LogGCOp(7da15c234f0b4e67823f676bcdfd74fd): free 20743880 bytes of WAL
I20260812 06:19:05.659569 13888 log_reader.cc:385] T 7da15c234f0b4e67823f676bcdfd74fd: removed 2 log segments from log reader
I20260812 06:19:05.659614 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000001 (ops 1-6)
I20260812 06:19:05.659647 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000002 (ops 7-11)
I20260812 06:19:05.663151 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: LogGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:05.663482 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:05.673691 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.674155 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd): 20513816 bytes on disk
I20260812 06:19:05.674744 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.675318 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:05.828805 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.153s	user 0.113s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":502,"lbm_read_time_us":11607,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23575,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":320,"threads_started":5,"update_count":2000}
I20260812 06:19:05.829335 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:05.864110 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.035s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13393,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.864558 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:05.874485 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.874974 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:05.993283 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.118s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":123,"lbm_read_time_us":9691,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19549,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:05.993835 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:06.038584 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.045s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.039140 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:06.049152 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.049857 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:06.166744 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.117s	user 0.078s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":755,"lbm_read_time_us":8843,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19884,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:19:06.167356 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:06.204970 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.037s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14353,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.205502 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:06.215473 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.215907 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:06.332208 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.116s	user 0.091s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":385,"lbm_read_time_us":8141,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21425,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:19:06.332732 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:06.378561 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.045s	user 0.027s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13973,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.379213 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:06.394416 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.394878 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:06.536427 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.141s	user 0.081s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":800,"lbm_read_time_us":10534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21825,"lbm_writes_lt_1ms":443,"mutex_wait_us":287,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.537016 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:06.581067 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.044s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12427,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.581645 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:06.597170 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.597841 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:06.726562 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.129s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":583,"lbm_read_time_us":7892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25158,"lbm_writes_lt_1ms":443,"mutex_wait_us":267,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:06.727289 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:06.765395 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.038s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15953,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.765941 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:06.781633 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.782130 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:06.812492 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1410,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:06.813212 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling LogGCOp(7da15c234f0b4e67823f676bcdfd74fd): free 112692363 bytes of WAL
I20260812 06:19:06.813428 13888 log_reader.cc:385] T 7da15c234f0b4e67823f676bcdfd74fd: removed 11 log segments from log reader
I20260812 06:19:06.813478 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000003 (ops 12-16)
I20260812 06:19:06.813511 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000004 (ops 17-21)
I20260812 06:19:06.813545 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000005 (ops 22-26)
I20260812 06:19:06.813578 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000006 (ops 27-31)
I20260812 06:19:06.813609 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000007 (ops 32-36)
I20260812 06:19:06.813640 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000008 (ops 37-41)
I20260812 06:19:06.813673 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000009 (ops 42-46)
I20260812 06:19:06.813704 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000010 (ops 47-51)
I20260812 06:19:06.813735 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000011 (ops 52-56)
I20260812 06:19:06.813767 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000012 (ops 57-61)
I20260812 06:19:06.813799 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000013 (ops 62-66)
I20260812 06:19:06.833513 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: LogGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.020s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:06.833936 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd): 447 bytes on disk
I20260812 06:19:06.834435 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.834918 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=3.181125
I20260812 06:19:06.849803 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.850216 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:06.863330 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.863880 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:07.035789 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.172s	user 0.133s	sys 0.031s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":567,"lbm_read_time_us":11477,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31856,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":38784,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:19:07.036329 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=14.095187
I20260812 06:19:07.080374 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.043s	user 0.021s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":16604,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.080988 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:07.097002 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.097548 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:07.249765 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.152s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":10969,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30591,"lbm_writes_lt_1ms":543,"mutex_wait_us":256,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:19:07.250571 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=11.118625
I20260812 06:19:07.279795 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.029s	user 0.014s	sys 0.012s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":12213,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":1550}
I20260812 06:19:07.280246 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:07.294402 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4651,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.295074 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:07.418823 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.123s	user 0.109s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":9251,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22570,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:19:07.419764 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:07.450649 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.031s	user 0.010s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12972,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.451140 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:07.462585 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.463129 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:07.578908 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.116s	user 0.091s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":7232,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22797,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":232832,"update_count":2000}
I20260812 06:19:07.579464 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:07.627933 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.048s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13334,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.628598 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:07.643975 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.644593 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:07.792079 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.147s	user 0.103s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":11597,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22282,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2000}
I20260812 06:19:07.792627 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:07.833901 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.041s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12375,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.834506 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:07.844938 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.845577 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:07.960500 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.114s	user 0.094s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":7820,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20515,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:07.961197 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:07.997449 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.036s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":12873,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.998032 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:08.008560 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.009140 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:08.128185 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.119s	user 0.098s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":8703,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21079,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:19:08.128779 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:08.174345 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.045s	user 0.016s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13043,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.174985 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:08.185637 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.186180 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:08.226073 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.040s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1366,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1409,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:08.226824 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling LogGCOp(7da15c234f0b4e67823f676bcdfd74fd): free 132571311 bytes of WAL
I20260812 06:19:08.227065 13888 log_reader.cc:385] T 7da15c234f0b4e67823f676bcdfd74fd: removed 13 log segments from log reader
I20260812 06:19:08.227120 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000014 (ops 67-71)
I20260812 06:19:08.227169 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000015 (ops 72-76)
I20260812 06:19:08.227200 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000016 (ops 77-81)
I20260812 06:19:08.227231 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000017 (ops 82-86)
I20260812 06:19:08.227258 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000018 (ops 87-91)
I20260812 06:19:08.227291 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000019 (ops 92-96)
I20260812 06:19:08.227322 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000020 (ops 97-100)
I20260812 06:19:08.227348 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000021 (ops 101-105)
I20260812 06:19:08.227384 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000022 (ops 106-110)
I20260812 06:19:08.227414 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000023 (ops 111-115)
I20260812 06:19:08.227447 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000024 (ops 116-120)
I20260812 06:19:08.227475 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000025 (ops 121-124)
I20260812 06:19:08.227502 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000026 (ops 125-129)
I20260812 06:19:08.255270 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: LogGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:08.255697 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=3.181125
I20260812 06:19:08.271939 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.016s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3897,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:08.272445 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd): 483 bytes on disk
I20260812 06:19:08.272856 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.273478 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:08.283097 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3437,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.283592 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:08.477003 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.193s	user 0.113s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":142,"lbm_read_time_us":13942,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30173,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:08.479643 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=14.095187
I20260812 06:19:08.525008 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.045s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19518,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.525614 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:08.665817 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.140s	user 0.116s	sys 0.019s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":263,"lbm_read_time_us":8300,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22543,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:08.666464 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=11.118625
I20260812 06:19:08.702696 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15343,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.703258 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:08.715025 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.715559 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:08.842016 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.126s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":638,"lbm_read_time_us":9824,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22757,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24064,"update_count":2000}
I20260812 06:19:08.842604 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:08.879060 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.036s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12907,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.879654 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:08.891607 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.011s	user 0.009s	sys 0.000s 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:19:08.892478 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:09.019804 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":8037,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23686,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:19:09.020421 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:09.060154 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.040s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16427,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.060724 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:09.070828 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.071327 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:09.191720 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.120s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":8558,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22325,"lbm_writes_lt_1ms":443,"mutex_wait_us":80,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:09.192261 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:09.237638 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.045s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14452,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.238279 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:09.248725 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.249329 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:09.387977 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.138s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1162,"lbm_read_time_us":10507,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21663,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.388584 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:09.426813 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.038s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16324,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.427345 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:09.437656 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.438277 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:09.558521 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.120s	user 0.094s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":9476,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21309,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:19:09.559167 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=10.126437
I20260812 06:19:09.600286 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.041s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.600793 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:09.611101 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.611761 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:09.646390 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushMRSOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":318,"dirs.run_wall_time_us":2130,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2158,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:09.647171 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling LogGCOp(7da15c234f0b4e67823f676bcdfd74fd): free 121006697 bytes of WAL
I20260812 06:19:09.647413 13888 log_reader.cc:385] T 7da15c234f0b4e67823f676bcdfd74fd: removed 12 log segments from log reader
I20260812 06:19:09.647459 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000027 (ops 130-134)
I20260812 06:19:09.647490 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000028 (ops 135-138)
I20260812 06:19:09.647523 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000029 (ops 139-143)
I20260812 06:19:09.647549 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000030 (ops 144-148)
I20260812 06:19:09.647573 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000031 (ops 149-153)
I20260812 06:19:09.647604 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000032 (ops 154-158)
I20260812 06:19:09.647636 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000033 (ops 159-163)
I20260812 06:19:09.647668 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000034 (ops 164-168)
I20260812 06:19:09.647701 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000035 (ops 169-173)
I20260812 06:19:09.647734 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000036 (ops 174-178)
I20260812 06:19:09.647782 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000037 (ops 179-183)
I20260812 06:19:09.647815 13888 log.cc:1079] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: Deleting log segment in path: /tmp/dist-test-task9QArlB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539976554-13542-0/minicluster-data/ts-0-root/wals/7da15c234f0b4e67823f676bcdfd74fd/wal-000000038 (ops 184-188)
I20260812 06:19:09.670215 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: LogGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:09.670842 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd): 472 bytes on disk
I20260812 06:19:09.671483 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: UndoDeltaBlockGCOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.672143 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=3.181125
I20260812 06:19:09.693306 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.021s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7642,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:09.693921 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=2.188937
I20260812 06:19:09.704257 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3619,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.704860 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=1.000000
I20260812 06:19:09.886350 13542 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.548s	user 1.670s	sys 0.148s
I20260812 06:19:09.889091 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: MajorDeltaCompactionOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.184s	user 0.155s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":234,"lbm_read_time_us":12275,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35279,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16000,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:09.889631 13964 maintenance_manager.cc:419] P a1af48db3c8d48e1a510fda78bf58586: Scheduling FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd): perf score=14.095187
I20260812 06:19:09.914072 13542 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.027s	user 0.000s	sys 0.005s
I20260812 06:19:09.914737 13542 tablet_server.cc:179] TabletServer@127.13.57.129:0 shutting down...
I20260812 06:19:09.932412 13888 maintenance_manager.cc:643] P a1af48db3c8d48e1a510fda78bf58586: FlushDeltaMemStoresOp(7da15c234f0b4e67823f676bcdfd74fd) complete. Timing: real 0.042s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18721,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.932976 13542 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:09.933228 13542 tablet_replica.cc:333] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586: stopping tablet replica
I20260812 06:19:09.933368 13542 raft_consensus.cc:2243] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:09.933529 13542 raft_consensus.cc:2272] T 7da15c234f0b4e67823f676bcdfd74fd P a1af48db3c8d48e1a510fda78bf58586 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:09.946957 13542 tablet_server.cc:196] TabletServer@127.13.57.129:0 shutdown complete.
I20260812 06:19:09.949934 13542 master.cc:562] Master@127.13.57.190:43183 shutting down...
I20260812 06:19:09.952986 13542 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:09.953142 13542 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:09.953233 13542 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4cecc269c2064b10b92079167992f573: stopping tablet replica
I20260812 06:19:09.965416 13542 master.cc:584] Master@127.13.57.190:43183 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4881 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10052 ms total)

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