[==========] 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:17:24.573555 31660 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.235.62:45473
I20260812 06:17:24.574641 31660 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:17:24.575294 31660 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.582059 31673 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.582059 31668 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:17:24.582342 31660 server_base.cc:1061] running on GCE node
W20260812 06:17:24.582367 31669 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.582932 31660 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.583063 31660 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.583132 31660 hybrid_clock.cc:648] HybridClock initialized: now 1786515444583129 us; error 0 us; skew 500 ppm
I20260812 06:17:24.585207 31660 webserver.cc:533] Webserver started at http://127.30.235.62:43779/ using document root <none> and password file <none>
I20260812 06:17:24.585804 31660 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.585902 31660 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.586175 31660 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.587898 31660 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/master-0-root/instance:
uuid: "3c2c650039d24efeae80041f1d4a4bba"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-s11t"
I20260812 06:17:24.591722 31660 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.006s	sys 0.000s
I20260812 06:17:24.594151 31680 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.595396 31660 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:24.595547 31660 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/master-0-root
uuid: "3c2c650039d24efeae80041f1d4a4bba"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-s11t"
I20260812 06:17:24.595669 31660 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.622464 31660 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.623262 31660 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:17:24.623487 31660 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.632638 31660 rpc_server.cc:307] RPC server started. Bound to: 127.30.235.62:45473
I20260812 06:17:24.632761 31762 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.235.62:45473 every 8 connection(s)
I20260812 06:17:24.635097 31763 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.640848 31763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba: Bootstrap starting.
I20260812 06:17:24.643379 31763 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.644361 31763 log.cc:826] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:24.646438 31763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba: No bootstrap required, opened a new log
I20260812 06:17:24.649890 31763 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c2c650039d24efeae80041f1d4a4bba" member_type: VOTER }
I20260812 06:17:24.650075 31763 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.650167 31763 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3c2c650039d24efeae80041f1d4a4bba, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.650923 31763 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [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: "3c2c650039d24efeae80041f1d4a4bba" member_type: VOTER }
I20260812 06:17:24.651082 31763 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.651180 31763 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.651368 31763 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.652277 31763 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c2c650039d24efeae80041f1d4a4bba" member_type: VOTER }
I20260812 06:17:24.652858 31763 leader_election.cc:304] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [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: 3c2c650039d24efeae80041f1d4a4bba; no voters: 
I20260812 06:17:24.653256 31763 leader_election.cc:290] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.653467 31767 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.653767 31767 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 1 LEADER]: Becoming Leader. State: Replica: 3c2c650039d24efeae80041f1d4a4bba, State: Running, Role: LEADER
I20260812 06:17:24.654228 31767 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [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: "3c2c650039d24efeae80041f1d4a4bba" member_type: VOTER }
I20260812 06:17:24.654403 31763 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:24.656180 31768 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3c2c650039d24efeae80041f1d4a4bba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c2c650039d24efeae80041f1d4a4bba" member_type: VOTER } }
I20260812 06:17:24.656226 31769 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3c2c650039d24efeae80041f1d4a4bba. Latest consensus state: current_term: 1 leader_uuid: "3c2c650039d24efeae80041f1d4a4bba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c2c650039d24efeae80041f1d4a4bba" member_type: VOTER } }
I20260812 06:17:24.656311 31768 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.656334 31769 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.656791 31787 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:24.657047 31660 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:24.659238 31787 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:24.664093 31787 catalog_manager.cc:1383] Generated new cluster ID: 1899f30873da44fc98ca457751c6d17b
I20260812 06:17:24.664167 31787 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:24.680900 31787 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:24.682204 31787 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:24.691253 31787 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba: Generated new TSK 0
I20260812 06:17:24.692035 31787 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:24.722203 31660 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.725425 31805 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.725395 31801 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.725415 31803 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.725873 31660 server_base.cc:1061] running on GCE node
I20260812 06:17:24.726085 31660 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.726137 31660 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.726156 31660 hybrid_clock.cc:648] HybridClock initialized: now 1786515444726156 us; error 0 us; skew 500 ppm
I20260812 06:17:24.727195 31660 webserver.cc:533] Webserver started at http://127.30.235.1:37631/ using document root <none> and password file <none>
I20260812 06:17:24.727409 31660 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.727465 31660 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.727581 31660 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.728010 31660 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/instance:
uuid: "635f7c020a1c498aaaf1769b4be10a42"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-s11t"
I20260812 06:17:24.729763 31660 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:24.730859 31812 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.731124 31660 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:24.731197 31660 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root
uuid: "635f7c020a1c498aaaf1769b4be10a42"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-s11t"
I20260812 06:17:24.731294 31660 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.752034 31660 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.753017 31660 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.753585 31660 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:24.754504 31660 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:24.754556 31660 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.754630 31660 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:24.754673 31660 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.761880 31660 rpc_server.cc:307] RPC server started. Bound to: 127.30.235.1:39849
I20260812 06:17:24.761957 31911 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.235.1:39849 every 8 connection(s)
I20260812 06:17:24.775574 31912 heartbeater.cc:344] Connected to a master server at 127.30.235.62:45473
I20260812 06:17:24.775841 31912 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:24.776371 31912 heartbeater.cc:507] Master 127.30.235.62:45473 requested a full tablet report, sending...
I20260812 06:17:24.777931 31709 ts_manager.cc:194] Registered new tserver with Master: 635f7c020a1c498aaaf1769b4be10a42 (127.30.235.1:39849)
I20260812 06:17:24.778609 31660 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016072095s
I20260812 06:17:24.779542 31709 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48120
I20260812 06:17:24.788913 31709 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48126:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:24.803401 31859 tablet_service.cc:1511] Processing CreateTablet for tablet 0be6b9e0cf044e27b16ee7ca34e4aa03 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1cdc43fde14f4d1296b6d2753f9c7edc]), partition=
I20260812 06:17:24.803885 31859 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0be6b9e0cf044e27b16ee7ca34e4aa03. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.806414 31934 tablet_bootstrap.cc:492] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Bootstrap starting.
I20260812 06:17:24.807680 31934 tablet_bootstrap.cc:654] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.808904 31934 tablet_bootstrap.cc:492] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: No bootstrap required, opened a new log
I20260812 06:17:24.809032 31934 ts_tablet_manager.cc:1403] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:24.809507 31934 raft_consensus.cc:359] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "635f7c020a1c498aaaf1769b4be10a42" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 39849 } }
I20260812 06:17:24.809633 31934 raft_consensus.cc:385] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.809682 31934 raft_consensus.cc:740] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 635f7c020a1c498aaaf1769b4be10a42, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.809863 31934 consensus_queue.cc:260] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [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: "635f7c020a1c498aaaf1769b4be10a42" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 39849 } }
I20260812 06:17:24.809978 31934 raft_consensus.cc:399] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.810053 31934 raft_consensus.cc:493] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.810113 31934 raft_consensus.cc:3060] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.810910 31934 raft_consensus.cc:515] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "635f7c020a1c498aaaf1769b4be10a42" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 39849 } }
I20260812 06:17:24.811066 31934 leader_election.cc:304] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [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: 635f7c020a1c498aaaf1769b4be10a42; no voters: 
I20260812 06:17:24.811288 31934 leader_election.cc:290] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.811430 31936 raft_consensus.cc:2804] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.811650 31934 ts_tablet_manager.cc:1434] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:24.811846 31912 heartbeater.cc:499] Master 127.30.235.62:45473 was elected leader, sending a full tablet report...
I20260812 06:17:24.811709 31936 raft_consensus.cc:697] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 1 LEADER]: Becoming Leader. State: Replica: 635f7c020a1c498aaaf1769b4be10a42, State: Running, Role: LEADER
I20260812 06:17:24.812280 31936 consensus_queue.cc:237] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [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: "635f7c020a1c498aaaf1769b4be10a42" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 39849 } }
I20260812 06:17:24.815173 31709 catalog_manager.cc:5719] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 reported cstate change: term changed from 0 to 1, leader changed from <none> to 635f7c020a1c498aaaf1769b4be10a42 (127.30.235.1). New cstate: current_term: 1 leader_uuid: "635f7c020a1c498aaaf1769b4be10a42" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "635f7c020a1c498aaaf1769b4be10a42" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 39849 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:24.888360 31660 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.018s	sys 0.012s
I20260812 06:17:25.013362 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=15.086190
I20260812 06:17:25.190011 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.176s	user 0.137s	sys 0.032s Metrics: {"bytes_written":12922847,"cfile_init":1,"compiler_manager_pool.queue_time_us":321,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":683,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42185,"lbm_writes_lt_1ms":672,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":165248,"thread_start_us":184,"threads_started":1,"update_count":1575}
I20260812 06:17:25.191336 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): 12308958 bytes on disk
I20260812 06:17:25.191951 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) 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:17:25.192512 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=3.181125
I20260812 06:17:25.210429 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5046222,"delete_count":0,"lbm_write_time_us":7159,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:17:25.210922 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): free 11976772 bytes of WAL
I20260812 06:17:25.211217 31821 log_reader.cc:385] T 0be6b9e0cf044e27b16ee7ca34e4aa03: removed 1 log segments from log reader
I20260812 06:17:25.211299 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000001 (ops 1-6)
I20260812 06:17:25.215006 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:25.215411 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.196750
I20260812 06:17:25.226205 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:17:25.226711 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:25.429929 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.203s	user 0.143s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":934,"lbm_read_time_us":13516,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33369,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":343,"threads_started":5,"update_count":2500}
I20260812 06:17:25.430548 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:25.486109 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.055s	user 0.014s	sys 0.040s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24184,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.486609 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:25.498147 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.498550 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:25.658134 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.159s	user 0.118s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":11024,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31492,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:25.658720 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=10.126437
I20260812 06:17:25.709466 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.051s	user 0.037s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22173,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.710289 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:25.736946 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.026s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.737452 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:25.747574 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.748181 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:25.898237 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.150s	user 0.113s	sys 0.033s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733841,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":110,"lbm_read_time_us":10730,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30260,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:25.899049 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=11.118625
I20260812 06:17:25.940294 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.041s	user 0.014s	sys 0.022s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16165,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:25.941094 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:25.955003 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.955469 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:25.968515 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4970,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.968971 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:26.122087 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.153s	user 0.132s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":853,"lbm_read_time_us":10606,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30259,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:26.123718 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=10.126437
I20260812 06:17:26.154767 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.031s	user 0.013s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13604,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.155405 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:26.169003 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.169562 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:26.300242 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.130s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":10243,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24330,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":55552,"update_count":2000}
I20260812 06:17:26.300872 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=10.126437
I20260812 06:17:26.351545 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.051s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15254,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.352190 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:26.370311 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6787,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.370934 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:26.424932 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.054s	user 0.039s	sys 0.002s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":143,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1466,"drs_written":1,"lbm_read_time_us":172,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1823,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:26.425814 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): free 121006453 bytes of WAL
I20260812 06:17:26.426069 31821 log_reader.cc:385] T 0be6b9e0cf044e27b16ee7ca34e4aa03: removed 12 log segments from log reader
I20260812 06:17:26.426122 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000002 (ops 7-11)
I20260812 06:17:26.426203 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000003 (ops 12-16)
I20260812 06:17:26.426261 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000004 (ops 17-21)
I20260812 06:17:26.426319 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000005 (ops 22-26)
I20260812 06:17:26.426371 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000006 (ops 27-30)
I20260812 06:17:26.426429 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000007 (ops 31-35)
I20260812 06:17:26.426473 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000008 (ops 36-40)
I20260812 06:17:26.426519 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000009 (ops 41-45)
I20260812 06:17:26.426560 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000010 (ops 46-50)
I20260812 06:17:26.426602 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000011 (ops 51-55)
I20260812 06:17:26.426673 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000012 (ops 56-60)
I20260812 06:17:26.426728 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000013 (ops 61-65)
I20260812 06:17:26.454664 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.029s	user 0.003s	sys 0.024s Metrics: {}
I20260812 06:17:26.455091 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): 448 bytes on disk
I20260812 06:17:26.455708 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.456305 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=3.181125
I20260812 06:17:26.472290 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.016s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4590,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:26.472868 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:26.486210 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5018,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.486766 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:26.697701 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.211s	user 0.140s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":635,"lbm_read_time_us":14501,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34784,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13824,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:17:26.698379 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:26.755317 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.057s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23810,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.755831 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:26.901437 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.145s	user 0.096s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":91,"lbm_read_time_us":11009,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23083,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.902194 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=11.118625
I20260812 06:17:26.934188 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.032s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12553635,"delete_count":0,"lbm_write_time_us":13647,"lbm_writes_lt_1ms":309,"reinsert_count":0,"update_count":1530}
I20260812 06:17:26.934741 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:26.954205 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.019s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":6268,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:26.954721 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:27.107398 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.152s	user 0.110s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631306,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":775,"lbm_read_time_us":8295,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29659,"lbm_writes_lt_1ms":443,"mutex_wait_us":370,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:27.108063 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=11.118625
I20260812 06:17:27.157011 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.049s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20021,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:27.157626 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.170502 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.170980 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.181509 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3840,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.181973 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:27.327752 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.146s	user 0.104s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1352,"lbm_read_time_us":10978,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29220,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:17:27.328260 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=10.126437
I20260812 06:17:27.368600 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.040s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17851,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.369222 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.379910 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.380625 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:27.510562 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.130s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":9408,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23457,"lbm_writes_lt_1ms":443,"mutex_wait_us":298,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:27.511209 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=10.126437
I20260812 06:17:27.564641 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.053s	user 0.018s	sys 0.029s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":23939,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.565160 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.594843 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.030s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.595330 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.607084 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.607607 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:27.793115 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.185s	user 0.107s	sys 0.074s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733842,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":530,"lbm_read_time_us":12556,"lbm_reads_lt_1ms":573,"lbm_write_time_us":37816,"lbm_writes_lt_1ms":543,"mutex_wait_us":104,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:27.793947 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:27.852918 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.059s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20483,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.853487 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.867755 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.868350 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:27.908195 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.040s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1591,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1692,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:27.909049 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): free 120553338 bytes of WAL
I20260812 06:17:27.909348 31821 log_reader.cc:385] T 0be6b9e0cf044e27b16ee7ca34e4aa03: removed 12 log segments from log reader
I20260812 06:17:27.909420 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000014 (ops 66-70)
I20260812 06:17:27.909461 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000015 (ops 71-75)
I20260812 06:17:27.909499 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000016 (ops 76-80)
I20260812 06:17:27.909539 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000017 (ops 81-84)
I20260812 06:17:27.909574 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000018 (ops 85-89)
I20260812 06:17:27.909603 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000019 (ops 90-94)
I20260812 06:17:27.909634 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000020 (ops 95-99)
I20260812 06:17:27.909663 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000021 (ops 100-104)
I20260812 06:17:27.909700 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000022 (ops 105-109)
I20260812 06:17:27.909739 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000023 (ops 110-114)
I20260812 06:17:27.909762 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000024 (ops 115-118)
I20260812 06:17:27.909793 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000025 (ops 119-123)
I20260812 06:17:27.944659 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:27.945155 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): 460 bytes on disk
I20260812 06:17:27.945663 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.946262 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.971957 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.025s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.972518 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:27.984252 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.984953 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:28.239423 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.254s	user 0.187s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938786,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1018,"lbm_read_time_us":19325,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44569,"lbm_writes_lt_1ms":743,"mutex_wait_us":967,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:17:28.240290 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=15.087375
I20260812 06:17:28.303968 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.063s	user 0.045s	sys 0.012s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":27032,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:28.304541 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:28.315380 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.315950 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:28.329523 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.013s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5278,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.330031 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:28.506843 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.177s	user 0.118s	sys 0.050s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836240,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":281,"lbm_read_time_us":12165,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35916,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":3000}
I20260812 06:17:28.507601 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:28.566378 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.059s	user 0.015s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19895,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.566919 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:28.578155 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.578886 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:28.754410 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.175s	user 0.143s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1123,"lbm_read_time_us":13314,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32503,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":2500}
I20260812 06:17:28.755012 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:28.815590 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.060s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23884,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.816069 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:28.827695 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.828481 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:28.992636 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.164s	user 0.126s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":10117,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29737,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:17:28.993468 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=11.118625
I20260812 06:17:29.031785 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.038s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16580,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.032328 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:29.058264 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.026s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4683,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.058969 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:29.074688 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.075351 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:29.262712 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.187s	user 0.112s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1039,"lbm_read_time_us":12876,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29742,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.263468 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:29.319175 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.055s	user 0.040s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24343,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.319849 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:29.359073 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushMRSOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.039s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":451,"dirs.run_wall_time_us":1670,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1494,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":9984}
I20260812 06:17:29.360055 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): 447 bytes on disk
I20260812 06:17:29.360524 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: UndoDeltaBlockGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.361132 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=3.181125
I20260812 06:17:29.380107 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.019s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7033,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:29.380565 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03): free 112239529 bytes of WAL
I20260812 06:17:29.380820 31821 log_reader.cc:385] T 0be6b9e0cf044e27b16ee7ca34e4aa03: removed 11 log segments from log reader
I20260812 06:17:29.380862 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000026 (ops 124-128)
I20260812 06:17:29.380892 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000027 (ops 129-133)
I20260812 06:17:29.380946 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000028 (ops 134-138)
I20260812 06:17:29.381013 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000029 (ops 139-143)
I20260812 06:17:29.381088 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000030 (ops 144-148)
I20260812 06:17:29.381125 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000031 (ops 149-152)
I20260812 06:17:29.381155 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000032 (ops 153-157)
I20260812 06:17:29.381191 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000033 (ops 158-162)
I20260812 06:17:29.381227 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000034 (ops 163-167)
I20260812 06:17:29.381268 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000035 (ops 168-172)
I20260812 06:17:29.381307 31821 log.cc:1079] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/0be6b9e0cf044e27b16ee7ca34e4aa03/wal-000000036 (ops 173-177)
I20260812 06:17:29.406884 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: LogGCOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:29.407377 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:29.430994 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.023s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4231,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.431555 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:29.446909 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.447571 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:29.662020 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.214s	user 0.145s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1277,"lbm_read_time_us":15733,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41942,"lbm_writes_lt_1ms":743,"mutex_wait_us":112,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":124,"threads_started":1,"update_count":3500}
I20260812 06:17:29.662861 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:29.724413 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.061s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27186,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.724983 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:29.751039 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.026s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.751590 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=2.188937
I20260812 06:17:29.764143 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.764780 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:29.938056 31660 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.050s	user 1.930s	sys 0.104s
I20260812 06:17:29.940505 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.176s	user 0.125s	sys 0.046s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836253,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":278,"lbm_read_time_us":11817,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35969,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":3000}
I20260812 06:17:29.941169 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=14.095187
I20260812 06:17:29.986107 31660 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.047s	user 0.003s	sys 0.004s
I20260812 06:17:29.986932 31660 tablet_server.cc:179] TabletServer@127.30.235.1:0 shutting down...
I20260812 06:17:30.001463 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: FlushDeltaMemStoresOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.060s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25260,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.004206 31913 maintenance_manager.cc:419] P 635f7c020a1c498aaaf1769b4be10a42: Scheduling MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03): perf score=1.000000
I20260812 06:17:30.135653 31821 maintenance_manager.cc:643] P 635f7c020a1c498aaaf1769b4be10a42: MajorDeltaCompactionOp(0be6b9e0cf044e27b16ee7ca34e4aa03) complete. Timing: real 0.131s	user 0.107s	sys 0.023s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":401,"cfile_cache_miss_bytes":16409768,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1430,"lbm_read_time_us":7382,"lbm_reads_lt_1ms":413,"lbm_write_time_us":26742,"lbm_writes_lt_1ms":443,"mutex_wait_us":541,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:17:30.136765 31660 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:30.137192 31660 tablet_replica.cc:333] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42: stopping tablet replica
I20260812 06:17:30.137455 31660 raft_consensus.cc:2243] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:30.137722 31660 raft_consensus.cc:2272] T 0be6b9e0cf044e27b16ee7ca34e4aa03 P 635f7c020a1c498aaaf1769b4be10a42 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:30.153559 31660 tablet_server.cc:196] TabletServer@127.30.235.1:0 shutdown complete.
I20260812 06:17:30.176667 31660 master.cc:562] Master@127.30.235.62:45473 shutting down...
I20260812 06:17:30.181300 31660 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:30.181494 31660 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:30.181577 31660 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3c2c650039d24efeae80041f1d4a4bba: stopping tablet replica
I20260812 06:17:30.194588 31660 master.cc:584] Master@127.30.235.62:45473 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5736 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:30.309005 31660 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.235.62:36575
I20260812 06:17:30.309461 31660 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:30.311914 31960 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.311897 31959 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.311790 31966 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:30.311980 31660 server_base.cc:1061] running on GCE node
I20260812 06:17:30.312371 31660 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:30.312412 31660 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:30.312427 31660 hybrid_clock.cc:648] HybridClock initialized: now 1786515450312428 us; error 0 us; skew 500 ppm
I20260812 06:17:30.313907 31660 webserver.cc:533] Webserver started at http://127.30.235.62:44703/ using document root <none> and password file <none>
I20260812 06:17:30.314046 31660 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:30.314087 31660 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:30.314144 31660 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:30.314496 31660 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/master-0-root/instance:
uuid: "68bb1810ce5145879494675d34428853"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-s11t"
I20260812 06:17:30.315986 31660 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:30.317049 31974 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.317392 31660 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:30.317492 31660 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/master-0-root
uuid: "68bb1810ce5145879494675d34428853"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-s11t"
I20260812 06:17:30.317592 31660 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:30.327401 31660 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:30.327894 31660 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:30.332587 31660 rpc_server.cc:307] RPC server started. Bound to: 127.30.235.62:36575
I20260812 06:17:30.334134 32054 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.235.62:36575 every 8 connection(s)
I20260812 06:17:30.334352 32056 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:30.351987 32056 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853: Bootstrap starting.
I20260812 06:17:30.352865 32056 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:30.353979 32056 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853: No bootstrap required, opened a new log
I20260812 06:17:30.354377 32056 raft_consensus.cc:359] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68bb1810ce5145879494675d34428853" member_type: VOTER }
I20260812 06:17:30.354467 32056 raft_consensus.cc:385] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:30.354490 32056 raft_consensus.cc:740] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 68bb1810ce5145879494675d34428853, State: Initialized, Role: FOLLOWER
I20260812 06:17:30.354648 32056 consensus_queue.cc:260] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [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: "68bb1810ce5145879494675d34428853" member_type: VOTER }
I20260812 06:17:30.354751 32056 raft_consensus.cc:399] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:30.354776 32056 raft_consensus.cc:493] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:30.354810 32056 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:30.355494 32056 raft_consensus.cc:515] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68bb1810ce5145879494675d34428853" member_type: VOTER }
I20260812 06:17:30.355602 32056 leader_election.cc:304] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [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: 68bb1810ce5145879494675d34428853; no voters: 
I20260812 06:17:30.355762 32056 leader_election.cc:290] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:30.355904 32063 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:30.356189 32063 raft_consensus.cc:697] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 1 LEADER]: Becoming Leader. State: Replica: 68bb1810ce5145879494675d34428853, State: Running, Role: LEADER
I20260812 06:17:30.356308 32056 sys_catalog.cc:565] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:30.356335 32063 consensus_queue.cc:237] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [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: "68bb1810ce5145879494675d34428853" member_type: VOTER }
I20260812 06:17:30.356801 32065 sys_catalog.cc:455] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "68bb1810ce5145879494675d34428853" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68bb1810ce5145879494675d34428853" member_type: VOTER } }
I20260812 06:17:30.356855 32066 sys_catalog.cc:455] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 68bb1810ce5145879494675d34428853. Latest consensus state: current_term: 1 leader_uuid: "68bb1810ce5145879494675d34428853" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68bb1810ce5145879494675d34428853" member_type: VOTER } }
I20260812 06:17:30.356957 32065 sys_catalog.cc:458] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:30.356977 32066 sys_catalog.cc:458] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:30.357674 32070 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:30.358453 32070 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:30.358690 31660 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:30.360466 32070 catalog_manager.cc:1383] Generated new cluster ID: 8f5990ffd2894ce3b9dfa4dfb7c88c24
I20260812 06:17:30.360550 32070 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:30.368103 32070 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:30.368649 32070 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:30.383319 32070 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853: Generated new TSK 0
I20260812 06:17:30.383595 32070 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:30.391224 31660 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:30.393537 32089 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:17:30.393756 31660 server_base.cc:1061] running on GCE node
W20260812 06:17:30.393761 32093 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.393888 32097 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:30.394102 31660 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:30.394145 31660 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:30.394161 31660 hybrid_clock.cc:648] HybridClock initialized: now 1786515450394162 us; error 0 us; skew 500 ppm
I20260812 06:17:30.394917 31660 webserver.cc:533] Webserver started at http://127.30.235.1:36655/ using document root <none> and password file <none>
I20260812 06:17:30.395051 31660 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:30.395095 31660 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:30.395146 31660 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:30.395504 31660 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/instance:
uuid: "0f0685759c054c618747b972bd087db8"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-s11t"
I20260812 06:17:30.397105 31660 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:30.398015 32105 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.398296 31660 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:30.398389 31660 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root
uuid: "0f0685759c054c618747b972bd087db8"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-s11t"
I20260812 06:17:30.398480 31660 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:30.405604 31660 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:30.406011 31660 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:30.406334 31660 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:30.406826 31660 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:30.406893 31660 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.406951 31660 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:30.406987 31660 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.411602 31660 rpc_server.cc:307] RPC server started. Bound to: 127.30.235.1:34205
I20260812 06:17:30.411643 32207 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.235.1:34205 every 8 connection(s)
I20260812 06:17:30.420852 32208 heartbeater.cc:344] Connected to a master server at 127.30.235.62:36575
I20260812 06:17:30.420975 32208 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:30.421301 32208 heartbeater.cc:507] Master 127.30.235.62:36575 requested a full tablet report, sending...
I20260812 06:17:30.422053 32001 ts_manager.cc:194] Registered new tserver with Master: 0f0685759c054c618747b972bd087db8 (127.30.235.1:34205)
I20260812 06:17:30.422076 31660 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010045361s
I20260812 06:17:30.422907 32001 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52944
I20260812 06:17:30.430218 32001 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52948:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:30.440039 32155 tablet_service.cc:1511] Processing CreateTablet for tablet 654a3b74a706493e9cfadb97424b21fd (DEFAULT_TABLE table=heavy-update-compaction-test [id=a1140d925111498197cb70b097a70c16]), partition=
I20260812 06:17:30.440387 32155 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 654a3b74a706493e9cfadb97424b21fd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:30.442773 32228 tablet_bootstrap.cc:492] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Bootstrap starting.
I20260812 06:17:30.443612 32228 tablet_bootstrap.cc:654] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:30.444947 32228 tablet_bootstrap.cc:492] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: No bootstrap required, opened a new log
I20260812 06:17:30.445065 32228 ts_tablet_manager.cc:1403] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:30.445604 32228 raft_consensus.cc:359] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f0685759c054c618747b972bd087db8" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 34205 } }
I20260812 06:17:30.445735 32228 raft_consensus.cc:385] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:30.445809 32228 raft_consensus.cc:740] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0f0685759c054c618747b972bd087db8, State: Initialized, Role: FOLLOWER
I20260812 06:17:30.445983 32228 consensus_queue.cc:260] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [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: "0f0685759c054c618747b972bd087db8" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 34205 } }
I20260812 06:17:30.446087 32228 raft_consensus.cc:399] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:30.446151 32228 raft_consensus.cc:493] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:30.446244 32228 raft_consensus.cc:3060] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:30.447028 32228 raft_consensus.cc:515] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f0685759c054c618747b972bd087db8" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 34205 } }
I20260812 06:17:30.447151 32228 leader_election.cc:304] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [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: 0f0685759c054c618747b972bd087db8; no voters: 
I20260812 06:17:30.447386 32228 leader_election.cc:290] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:30.447579 32233 raft_consensus.cc:2804] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:30.447714 32228 ts_tablet_manager.cc:1434] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:30.447772 32233 raft_consensus.cc:697] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 1 LEADER]: Becoming Leader. State: Replica: 0f0685759c054c618747b972bd087db8, State: Running, Role: LEADER
I20260812 06:17:30.447748 32208 heartbeater.cc:499] Master 127.30.235.62:36575 was elected leader, sending a full tablet report...
I20260812 06:17:30.447960 32233 consensus_queue.cc:237] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [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: "0f0685759c054c618747b972bd087db8" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 34205 } }
I20260812 06:17:30.449479 32001 catalog_manager.cc:5719] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0f0685759c054c618747b972bd087db8 (127.30.235.1). New cstate: current_term: 1 leader_uuid: "0f0685759c054c618747b972bd087db8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f0685759c054c618747b972bd087db8" member_type: VOTER last_known_addr { host: "127.30.235.1" port: 34205 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:30.511541 31660 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.019s	sys 0.004s
I20260812 06:17:30.662554 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushMRSOp(654a3b74a706493e9cfadb97424b21fd): perf score=19.054940
I20260812 06:17:30.823414 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushMRSOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.160s	user 0.110s	sys 0.047s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":997,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42694,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:30.824110 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling LogGCOp(654a3b74a706493e9cfadb97424b21fd): free 20290830 bytes of WAL
I20260812 06:17:30.824364 32113 log_reader.cc:385] T 654a3b74a706493e9cfadb97424b21fd: removed 2 log segments from log reader
I20260812 06:17:30.824414 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000001 (ops 1-6)
I20260812 06:17:30.824446 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000002 (ops 7-10)
I20260812 06:17:30.829560 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: LogGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:30.829962 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd): 16411397 bytes on disk
I20260812 06:17:30.830437 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.830862 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:30.858600 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.028s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.859076 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:30.884929 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.026s	user 0.011s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.885687 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:31.086040 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.200s	user 0.132s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":871,"lbm_read_time_us":15526,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30728,"lbm_writes_lt_1ms":543,"mutex_wait_us":222,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":380,"threads_started":5,"update_count":2500}
I20260812 06:17:31.086766 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=11.118625
I20260812 06:17:31.124055 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.037s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16139,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.124583 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:31.140281 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5614,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.140893 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:31.274187 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.133s	user 0.091s	sys 0.041s 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":492,"lbm_read_time_us":9880,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26951,"lbm_writes_lt_1ms":443,"mutex_wait_us":319,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:17:31.277096 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:31.317287 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17631,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.317830 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:31.335834 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.336335 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:31.486205 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.150s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2536,"lbm_read_time_us":9320,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29802,"lbm_writes_lt_1ms":443,"mutex_wait_us":585,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:17:31.487025 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:31.525951 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.039s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14660,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.526420 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:31.536996 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.537827 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:31.666805 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.129s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":9655,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25758,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.667495 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=11.118625
I20260812 06:17:31.712563 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.045s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14924,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.713241 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:31.725328 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.725832 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:31.872957 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.147s	user 0.090s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":353,"lbm_read_time_us":11332,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24343,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:31.873574 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:31.905258 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.032s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13487,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.905891 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:31.921231 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.921779 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:32.055022 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.133s	user 0.102s	sys 0.028s 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":421,"lbm_read_time_us":9250,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26076,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:17:32.055686 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:32.103699 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.048s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17048,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.104225 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:32.114998 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.116120 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushMRSOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:32.149178 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushMRSOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.033s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1961,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:32.149822 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling LogGCOp(654a3b74a706493e9cfadb97424b21fd): free 121006373 bytes of WAL
I20260812 06:17:32.150056 32113 log_reader.cc:385] T 654a3b74a706493e9cfadb97424b21fd: removed 12 log segments from log reader
I20260812 06:17:32.150121 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000003 (ops 11-15)
I20260812 06:17:32.150174 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000004 (ops 16-20)
I20260812 06:17:32.150233 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000005 (ops 21-25)
I20260812 06:17:32.150275 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000006 (ops 26-30)
I20260812 06:17:32.150308 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000007 (ops 31-34)
I20260812 06:17:32.150362 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000008 (ops 35-39)
I20260812 06:17:32.150398 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000009 (ops 40-44)
I20260812 06:17:32.150434 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000010 (ops 45-49)
I20260812 06:17:32.150470 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000011 (ops 50-54)
I20260812 06:17:32.150507 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000012 (ops 55-59)
I20260812 06:17:32.150544 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000013 (ops 60-64)
I20260812 06:17:32.150580 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000014 (ops 65-69)
I20260812 06:17:32.177788 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: LogGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:32.178333 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=4.173312
I20260812 06:17:32.192304 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":5374416,"delete_count":0,"lbm_write_time_us":5715,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:17:32.192842 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd): 462 bytes on disk
I20260812 06:17:32.193272 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.193730 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.196750
I20260812 06:17:32.203614 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3528,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:17:32.204038 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:32.394825 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.191s	user 0.106s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":184,"lbm_read_time_us":12475,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38214,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:32.395565 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:32.453876 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.058s	user 0.021s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27196,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.454478 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:32.470706 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.471238 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:32.630123 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.159s	user 0.122s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":10280,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30005,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":39040,"update_count":2500}
I20260812 06:17:32.630810 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=11.118625
I20260812 06:17:32.671469 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.040s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17431,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:32.672235 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:32.691133 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.019s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6164,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.691783 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:32.856117 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.164s	user 0.102s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":724,"lbm_read_time_us":10244,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25790,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:17:32.856922 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:32.918488 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.061s	user 0.027s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24566,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.919085 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:32.937103 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6425,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.937623 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:33.114784 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.177s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":14165,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28598,"lbm_writes_lt_1ms":543,"mutex_wait_us":11,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:17:33.115522 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:33.193357 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.078s	user 0.035s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":40405,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.193898 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:33.206331 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.206861 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:33.379935 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.173s	user 0.135s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":470,"lbm_read_time_us":12947,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28998,"lbm_writes_lt_1ms":543,"mutex_wait_us":111,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:17:33.380714 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:33.448026 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.067s	user 0.036s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27113,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.449349 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=3.181125
I20260812 06:17:33.465054 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4389828,"delete_count":0,"lbm_write_time_us":5495,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:33.465543 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:33.479898 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3815483,"delete_count":0,"lbm_write_time_us":5477,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:33.480508 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:33.671401 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.191s	user 0.121s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877212,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":768,"lbm_read_time_us":15499,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31586,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:33.672119 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:33.727555 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.055s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22605,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.728122 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:33.740319 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.740967 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushMRSOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:33.774514 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushMRSOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1415,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1756,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:33.775211 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling LogGCOp(654a3b74a706493e9cfadb97424b21fd): free 124710368 bytes of WAL
I20260812 06:17:33.775501 32113 log_reader.cc:385] T 654a3b74a706493e9cfadb97424b21fd: removed 12 log segments from log reader
I20260812 06:17:33.775573 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000015 (ops 70-74)
I20260812 06:17:33.775609 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000016 (ops 75-79)
I20260812 06:17:33.775635 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000017 (ops 80-84)
I20260812 06:17:33.775667 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000018 (ops 85-89)
I20260812 06:17:33.775700 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000019 (ops 90-94)
I20260812 06:17:33.775733 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000020 (ops 95-99)
I20260812 06:17:33.775771 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000021 (ops 100-104)
I20260812 06:17:33.775800 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000022 (ops 105-109)
I20260812 06:17:33.775861 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000023 (ops 110-114)
I20260812 06:17:33.775890 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000024 (ops 115-119)
I20260812 06:17:33.775913 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000025 (ops 120-124)
I20260812 06:17:33.775941 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000026 (ops 125-129)
I20260812 06:17:33.808046 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: LogGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:33.808462 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd): 492 bytes on disk
I20260812 06:17:33.809023 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.809536 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=4.173312
I20260812 06:17:33.825109 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":6194895,"delete_count":0,"lbm_write_time_us":6417,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:17:33.825557 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:33.834105 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":2745,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:17:33.834628 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:34.076215 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.241s	user 0.157s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979699,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":525,"lbm_read_time_us":14358,"lbm_reads_lt_1ms":766,"lbm_write_time_us":46113,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:17:34.076987 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:34.125516 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.048s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21547,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.126163 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:34.149230 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.023s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:17:34.149796 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:34.312433 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.162s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":898,"lbm_read_time_us":10477,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31513,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:34.313066 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:34.365902 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.053s	user 0.015s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22937,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.366463 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:34.519232 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.153s	user 0.088s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":836,"lbm_read_time_us":11154,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25767,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.520020 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:34.566435 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.046s	user 0.037s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18529,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.567153 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:34.591437 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.024s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.591898 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:34.602747 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.603188 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:34.799649 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.196s	user 0.114s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1336,"lbm_read_time_us":12709,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31542,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:17:34.800370 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:34.854257 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.054s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21083,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.854758 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:34.866992 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.867519 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:35.021790 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.154s	user 0.130s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":312,"lbm_read_time_us":12308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28330,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:35.022528 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:35.053969 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.031s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.054538 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:35.069286 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.069759 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:35.198932 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.129s	user 0.082s	sys 0.047s 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":371,"lbm_read_time_us":9056,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24607,"lbm_writes_lt_1ms":443,"mutex_wait_us":122,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:35.199631 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=10.126437
I20260812 06:17:35.246167 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.046s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15366,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.246840 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:35.257977 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.258785 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushMRSOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:35.287357 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushMRSOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1548,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1410,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:35.288144 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling LogGCOp(654a3b74a706493e9cfadb97424b21fd): free 124710518 bytes of WAL
I20260812 06:17:35.288435 32113 log_reader.cc:385] T 654a3b74a706493e9cfadb97424b21fd: removed 12 log segments from log reader
I20260812 06:17:35.288498 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000027 (ops 130-134)
I20260812 06:17:35.288537 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000028 (ops 135-139)
I20260812 06:17:35.288559 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000029 (ops 140-144)
I20260812 06:17:35.288585 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000030 (ops 145-149)
I20260812 06:17:35.288610 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000031 (ops 150-154)
I20260812 06:17:35.288641 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000032 (ops 155-159)
I20260812 06:17:35.288667 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000033 (ops 160-164)
I20260812 06:17:35.288729 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000034 (ops 165-169)
I20260812 06:17:35.288754 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000035 (ops 170-174)
I20260812 06:17:35.288789 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000036 (ops 175-179)
I20260812 06:17:35.288821 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000037 (ops 180-184)
I20260812 06:17:35.288848 32113 log.cc:1079] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: Deleting log segment in path: /tmp/dist-test-task8QbKRz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515444562621-31660-0/minicluster-data/ts-0-root/wals/654a3b74a706493e9cfadb97424b21fd/wal-000000038 (ops 185-189)
I20260812 06:17:35.321633 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: LogGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.033s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:17:35.322039 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd): 462 bytes on disk
I20260812 06:17:35.322487 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: UndoDeltaBlockGCOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.323154 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:35.346473 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.023s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.346959 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=2.188937
I20260812 06:17:35.358186 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4338,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.359028 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd): perf score=1.000000
I20260812 06:17:35.536417 31660 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.025s	user 1.935s	sys 0.133s
I20260812 06:17:35.539330 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: MajorDeltaCompactionOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.180s	user 0.122s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":582,"lbm_read_time_us":12717,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36718,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:35.540047 32209 maintenance_manager.cc:419] P 0f0685759c054c618747b972bd087db8: Scheduling FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd): perf score=14.095187
I20260812 06:17:35.565897 31660 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.029s	user 0.002s	sys 0.000s
I20260812 06:17:35.566464 31660 tablet_server.cc:179] TabletServer@127.30.235.1:0 shutting down...
I20260812 06:17:35.592502 32113 maintenance_manager.cc:643] P 0f0685759c054c618747b972bd087db8: FlushDeltaMemStoresOp(654a3b74a706493e9cfadb97424b21fd) complete. Timing: real 0.052s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":21893,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.593273 31660 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:35.593564 31660 tablet_replica.cc:333] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8: stopping tablet replica
I20260812 06:17:35.593703 31660 raft_consensus.cc:2243] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.593851 31660 raft_consensus.cc:2272] T 654a3b74a706493e9cfadb97424b21fd P 0f0685759c054c618747b972bd087db8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.599637 31660 tablet_server.cc:196] TabletServer@127.30.235.1:0 shutdown complete.
I20260812 06:17:35.603223 31660 master.cc:562] Master@127.30.235.62:36575 shutting down...
I20260812 06:17:35.606559 31660 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.606763 31660 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.606865 31660 tablet_replica.cc:333] T 00000000000000000000000000000000 P 68bb1810ce5145879494675d34428853: stopping tablet replica
I20260812 06:17:35.619310 31660 master.cc:584] Master@127.30.235.62:36575 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5402 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11139 ms total)

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