[==========] 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:45.414305 11839 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.143.254:46291
I20260812 06:17:45.415287 11839 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:45.415887 11839 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.421998 11846 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:45.422019 11849 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:45.422169 11839 server_base.cc:1061] running on GCE node
W20260812 06:17:45.422374 11847 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:45.422899 11839 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.423000 11839 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:45.423044 11839 hybrid_clock.cc:648] HybridClock initialized: now 1786515465423042 us; error 0 us; skew 500 ppm
I20260812 06:17:45.424719 11839 webserver.cc:533] Webserver started at http://127.11.143.254:40827/ using document root <none> and password file <none>
I20260812 06:17:45.425241 11839 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.425321 11839 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.425558 11839 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.427191 11839 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/master-0-root/instance:
uuid: "84552ef1a8b749a48890f2b1281f91c0"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-gjw7"
I20260812 06:17:45.430650 11839 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.005s
I20260812 06:17:45.432642 11859 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:45.433669 11839 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:45.433782 11839 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/master-0-root
uuid: "84552ef1a8b749a48890f2b1281f91c0"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-gjw7"
I20260812 06:17:45.433871 11839 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-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:45.446128 11839 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.446736 11839 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:45.446887 11839 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.453840 11839 rpc_server.cc:307] RPC server started. Bound to: 127.11.143.254:46291
I20260812 06:17:45.453881 11974 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.143.254:46291 every 8 connection(s)
I20260812 06:17:45.456032 11977 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:45.461665 11977 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: Bootstrap starting.
I20260812 06:17:45.463989 11977 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.464867 11977 log.cc:826] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:45.466603 11977 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: No bootstrap required, opened a new log
I20260812 06:17:45.469342 11977 raft_consensus.cc:359] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "84552ef1a8b749a48890f2b1281f91c0" member_type: VOTER }
I20260812 06:17:45.469523 11977 raft_consensus.cc:385] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.469591 11977 raft_consensus.cc:740] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 84552ef1a8b749a48890f2b1281f91c0, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.470201 11977 consensus_queue.cc:260] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [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: "84552ef1a8b749a48890f2b1281f91c0" member_type: VOTER }
I20260812 06:17:45.470348 11977 raft_consensus.cc:399] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.470424 11977 raft_consensus.cc:493] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.470546 11977 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.471300 11977 raft_consensus.cc:515] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "84552ef1a8b749a48890f2b1281f91c0" member_type: VOTER }
I20260812 06:17:45.471725 11977 leader_election.cc:304] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [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: 84552ef1a8b749a48890f2b1281f91c0; no voters: 
I20260812 06:17:45.472025 11977 leader_election.cc:290] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.472148 11989 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.472419 11989 raft_consensus.cc:697] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 1 LEADER]: Becoming Leader. State: Replica: 84552ef1a8b749a48890f2b1281f91c0, State: Running, Role: LEADER
I20260812 06:17:45.472785 11989 consensus_queue.cc:237] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [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: "84552ef1a8b749a48890f2b1281f91c0" member_type: VOTER }
I20260812 06:17:45.472932 11977 sys_catalog.cc:565] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:45.474682 11995 sys_catalog.cc:455] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "84552ef1a8b749a48890f2b1281f91c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "84552ef1a8b749a48890f2b1281f91c0" member_type: VOTER } }
I20260812 06:17:45.474790 11995 sys_catalog.cc:458] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.475049 11996 sys_catalog.cc:455] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 84552ef1a8b749a48890f2b1281f91c0. Latest consensus state: current_term: 1 leader_uuid: "84552ef1a8b749a48890f2b1281f91c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "84552ef1a8b749a48890f2b1281f91c0" member_type: VOTER } }
I20260812 06:17:45.475122 11996 sys_catalog.cc:458] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.475189 11839 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:45.476915 12025 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:45.476977 12025 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:45.477052 12021 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:45.477790 12021 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:45.482234 12021 catalog_manager.cc:1383] Generated new cluster ID: 22ebbe8e23264f66bcc9ae94c3fa592c
I20260812 06:17:45.482297 12021 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:45.494099 12021 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:45.495260 12021 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:45.507704 12021 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: Generated new TSK 0
I20260812 06:17:45.508483 12021 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:45.540042 11839 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.543001 12034 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:45.543114 12032 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:45.543144 12038 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:45.543396 11839 server_base.cc:1061] running on GCE node
I20260812 06:17:45.543562 11839 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.543601 11839 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:45.543614 11839 hybrid_clock.cc:648] HybridClock initialized: now 1786515465543614 us; error 0 us; skew 500 ppm
I20260812 06:17:45.544446 11839 webserver.cc:533] Webserver started at http://127.11.143.193:43255/ using document root <none> and password file <none>
I20260812 06:17:45.544612 11839 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.544660 11839 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.544737 11839 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.545114 11839 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/instance:
uuid: "1ca8475a17b64b1496d3eb3a964778c7"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-gjw7"
I20260812 06:17:45.546679 11839 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:45.547716 12049 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:45.547986 11839 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:45.548060 11839 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root
uuid: "1ca8475a17b64b1496d3eb3a964778c7"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-gjw7"
I20260812 06:17:45.548141 11839 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-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:45.557431 11839 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.557886 11839 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.558395 11839 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:45.559316 11839 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:45.559373 11839 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.559425 11839 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:45.559460 11839 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.566315 11839 rpc_server.cc:307] RPC server started. Bound to: 127.11.143.193:34687
I20260812 06:17:45.566357 12172 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.143.193:34687 every 8 connection(s)
I20260812 06:17:45.575976 12175 heartbeater.cc:344] Connected to a master server at 127.11.143.254:46291
I20260812 06:17:45.576226 12175 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:45.576658 12175 heartbeater.cc:507] Master 127.11.143.254:46291 requested a full tablet report, sending...
I20260812 06:17:45.578095 11895 ts_manager.cc:194] Registered new tserver with Master: 1ca8475a17b64b1496d3eb3a964778c7 (127.11.143.193:34687)
I20260812 06:17:45.578166 11839 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011254958s
I20260812 06:17:45.579262 11895 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44816
I20260812 06:17:45.588251 11895 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44820:
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:45.602344 12110 tablet_service.cc:1511] Processing CreateTablet for tablet 680e4ec5972942b9bbe67c23ccfdb020 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e2545cc0d24242379f00440e436e13dc]), partition=
I20260812 06:17:45.602777 12110 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 680e4ec5972942b9bbe67c23ccfdb020. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:45.605111 12200 tablet_bootstrap.cc:492] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Bootstrap starting.
I20260812 06:17:45.606241 12200 tablet_bootstrap.cc:654] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.607445 12200 tablet_bootstrap.cc:492] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: No bootstrap required, opened a new log
I20260812 06:17:45.607554 12200 ts_tablet_manager.cc:1403] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:45.608038 12200 raft_consensus.cc:359] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1ca8475a17b64b1496d3eb3a964778c7" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 34687 } }
I20260812 06:17:45.608158 12200 raft_consensus.cc:385] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.608208 12200 raft_consensus.cc:740] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1ca8475a17b64b1496d3eb3a964778c7, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.608337 12200 consensus_queue.cc:260] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [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: "1ca8475a17b64b1496d3eb3a964778c7" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 34687 } }
I20260812 06:17:45.608429 12200 raft_consensus.cc:399] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.608469 12200 raft_consensus.cc:493] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.608512 12200 raft_consensus.cc:3060] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.609483 12200 raft_consensus.cc:515] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1ca8475a17b64b1496d3eb3a964778c7" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 34687 } }
I20260812 06:17:45.609628 12200 leader_election.cc:304] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [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: 1ca8475a17b64b1496d3eb3a964778c7; no voters: 
I20260812 06:17:45.609819 12200 leader_election.cc:290] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.610106 12207 raft_consensus.cc:2804] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.610198 12200 ts_tablet_manager.cc:1434] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:45.610376 12207 raft_consensus.cc:697] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 1 LEADER]: Becoming Leader. State: Replica: 1ca8475a17b64b1496d3eb3a964778c7, State: Running, Role: LEADER
I20260812 06:17:45.610569 12207 consensus_queue.cc:237] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [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: "1ca8475a17b64b1496d3eb3a964778c7" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 34687 } }
I20260812 06:17:45.610636 12175 heartbeater.cc:499] Master 127.11.143.254:46291 was elected leader, sending a full tablet report...
I20260812 06:17:45.613097 11895 catalog_manager.cc:5719] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1ca8475a17b64b1496d3eb3a964778c7 (127.11.143.193). New cstate: current_term: 1 leader_uuid: "1ca8475a17b64b1496d3eb3a964778c7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1ca8475a17b64b1496d3eb3a964778c7" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 34687 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:45.676719 11839 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.012s
I20260812 06:17:45.817420 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=19.054940
I20260812 06:17:45.997735 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.180s	user 0.146s	sys 0.033s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":49205,"compiler_manager_pool.run_cpu_time_us":166408,"compiler_manager_pool.run_wall_time_us":166600,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1737,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43624,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":182528,"thread_start_us":137,"threads_started":1,"update_count":1550}
I20260812 06:17:45.999107 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling LogGCOp(680e4ec5972942b9bbe67c23ccfdb020): free 20743880 bytes of WAL
I20260812 06:17:45.999444 12060 log_reader.cc:385] T 680e4ec5972942b9bbe67c23ccfdb020: removed 2 log segments from log reader
I20260812 06:17:45.999511 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000001 (ops 1-6)
I20260812 06:17:45.999552 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000002 (ops 7-11)
I20260812 06:17:46.003021 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: LogGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:46.003353 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.022992 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.019s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.023479 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.032678 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3393,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.033053 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020): 16411398 bytes on disk
I20260812 06:17:46.033589 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.034060 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:46.197217 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.163s	user 0.131s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":463,"lbm_read_time_us":10617,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27357,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":258,"threads_started":5,"update_count":2500}
I20260812 06:17:46.197813 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:46.234647 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.037s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.235107 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.250542 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.251029 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:46.364007 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.113s	user 0.090s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":7656,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21431,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:17:46.364560 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:46.408676 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.043s	user 0.022s	sys 0.018s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18977,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.409281 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.424793 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.425284 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:46.545104 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.120s	user 0.078s	sys 0.041s 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":957,"lbm_read_time_us":7688,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21575,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:17:46.545784 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:46.579965 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13137,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.580487 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.595500 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5472,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.596009 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:46.718037 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.122s	user 0.100s	sys 0.021s 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":349,"lbm_read_time_us":8033,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22960,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:17:46.718524 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:46.759894 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.041s	user 0.020s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14404,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.760510 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.770767 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.771543 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:46.915931 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.144s	user 0.123s	sys 0.021s 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":237,"lbm_read_time_us":10622,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23905,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:46.916419 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:46.963146 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.047s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15938,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.963618 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:46.973390 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.973932 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:47.091666 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.118s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":7743,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21563,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":47360,"update_count":2000}
I20260812 06:17:47.092132 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:47.126020 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.034s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13297,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.126493 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:47.137635 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.138151 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:47.164614 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":1195,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1524,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:47.165586 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling LogGCOp(680e4ec5972942b9bbe67c23ccfdb020): free 112239257 bytes of WAL
I20260812 06:17:47.165845 12060 log_reader.cc:385] T 680e4ec5972942b9bbe67c23ccfdb020: removed 11 log segments from log reader
I20260812 06:17:47.165903 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000003 (ops 12-16)
I20260812 06:17:47.165942 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000004 (ops 17-21)
I20260812 06:17:47.165977 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000005 (ops 22-26)
I20260812 06:17:47.166009 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000006 (ops 27-31)
I20260812 06:17:47.166039 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000007 (ops 32-36)
I20260812 06:17:47.166070 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000008 (ops 37-41)
I20260812 06:17:47.166100 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000009 (ops 42-46)
I20260812 06:17:47.166129 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000010 (ops 47-50)
I20260812 06:17:47.166160 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000011 (ops 51-55)
I20260812 06:17:47.166190 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000012 (ops 56-60)
I20260812 06:17:47.166220 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000013 (ops 61-65)
I20260812 06:17:47.187099 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: LogGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:47.187480 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020): 462 bytes on disk
I20260812 06:17:47.187938 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020) 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:47.188413 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=3.181125
I20260812 06:17:47.201234 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:47.201602 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:47.210469 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3143,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.210847 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:47.382196 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.171s	user 0.128s	sys 0.031s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":288,"lbm_read_time_us":11404,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30037,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:47.382709 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:47.433887 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.051s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22215,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.434492 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:47.451793 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.452199 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:47.602864 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.151s	user 0.106s	sys 0.032s 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":851,"lbm_read_time_us":10334,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26891,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:47.603483 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:47.662987 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.059s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21698,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.663492 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:47.673588 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.674220 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:47.852906 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.178s	user 0.106s	sys 0.064s 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":1019,"lbm_read_time_us":11755,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27967,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:47.853504 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:47.897470 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19227,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.898032 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:48.030665 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.132s	user 0.089s	sys 0.042s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":252,"lbm_read_time_us":9955,"lbm_reads_lt_1ms":467,"lbm_write_time_us":20374,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:48.031210 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=11.118625
I20260812 06:17:48.066727 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.035s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15095,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.067346 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.082352 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.082823 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:48.205483 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.123s	user 0.087s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":8666,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21871,"lbm_writes_lt_1ms":443,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35840,"update_count":2000}
I20260812 06:17:48.206202 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=11.118625
I20260812 06:17:48.235484 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.029s	user 0.010s	sys 0.017s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12414,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.235963 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.247066 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.247495 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:48.367233 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.120s	user 0.095s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":661,"lbm_read_time_us":8340,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23139,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:48.367846 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=10.126437
I20260812 06:17:48.402930 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.035s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.403425 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.418303 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5185,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.419296 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:48.445907 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.026s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":1116,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1604,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:48.446646 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling LogGCOp(680e4ec5972942b9bbe67c23ccfdb020): free 124710349 bytes of WAL
I20260812 06:17:48.446878 12060 log_reader.cc:385] T 680e4ec5972942b9bbe67c23ccfdb020: removed 12 log segments from log reader
I20260812 06:17:48.446939 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000014 (ops 66-70)
I20260812 06:17:48.446985 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000015 (ops 71-75)
I20260812 06:17:48.447019 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000016 (ops 76-80)
I20260812 06:17:48.447049 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000017 (ops 81-85)
I20260812 06:17:48.447077 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000018 (ops 86-90)
I20260812 06:17:48.447108 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000019 (ops 91-95)
I20260812 06:17:48.447140 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000020 (ops 96-100)
I20260812 06:17:48.447170 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000021 (ops 101-105)
I20260812 06:17:48.447196 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000022 (ops 106-110)
I20260812 06:17:48.447224 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000023 (ops 111-115)
I20260812 06:17:48.447253 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000024 (ops 116-120)
I20260812 06:17:48.447285 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000025 (ops 121-125)
I20260812 06:17:48.474012 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: LogGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:48.474444 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020): 448 bytes on disk
I20260812 06:17:48.474953 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.475493 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=3.181125
I20260812 06:17:48.492117 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6589,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:48.492507 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.502007 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3363,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.502789 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:48.668447 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.165s	user 0.099s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":679,"lbm_read_time_us":11152,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31709,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:17:48.668949 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:48.711853 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.043s	user 0.013s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17109,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.712286 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.722074 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.722477 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:48.873167 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.151s	user 0.110s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":11255,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26859,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22528,"update_count":2500}
I20260812 06:17:48.873852 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=12.110812
I20260812 06:17:48.916031 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.042s	user 0.019s	sys 0.019s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":18437,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":332,"reinsert_count":0,"update_count":1655}
I20260812 06:17:48.916565 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.935690 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.019s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:48.936124 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:48.945068 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3146,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.945510 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:49.119167 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.173s	user 0.133s	sys 0.033s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774780,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":715,"lbm_read_time_us":11315,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29767,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:17:49.119714 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:49.169042 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.049s	user 0.016s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17929,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.169648 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:49.179924 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.180609 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:49.337927 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.157s	user 0.109s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":964,"lbm_read_time_us":12141,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26134,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:49.338475 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:49.395074 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.056s	user 0.019s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20754,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.395596 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:49.405341 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.405748 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:49.573550 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.168s	user 0.121s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":94,"lbm_read_time_us":11295,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24855,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:49.574146 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=14.095187
I20260812 06:17:49.628154 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.054s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22418,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.628693 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:49.643436 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.645160 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:49.803238 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.158s	user 0.101s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":10561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25819,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:49.803717 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=11.118625
I20260812 06:17:49.837532 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.034s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13999,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:49.838080 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:49.851840 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.852411 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:49.905694 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushMRSOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.053s	user 0.038s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1325,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1596,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:49.906577 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020): 492 bytes on disk
I20260812 06:17:49.907012 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: UndoDeltaBlockGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:49.907519 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=3.181125
I20260812 06:17:49.920521 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3790,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:49.920997 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling LogGCOp(680e4ec5972942b9bbe67c23ccfdb020): free 132571586 bytes of WAL
I20260812 06:17:49.921221 12060 log_reader.cc:385] T 680e4ec5972942b9bbe67c23ccfdb020: removed 13 log segments from log reader
I20260812 06:17:49.921267 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000026 (ops 126-130)
I20260812 06:17:49.921329 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000027 (ops 131-135)
I20260812 06:17:49.921363 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000028 (ops 136-140)
I20260812 06:17:49.921389 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000029 (ops 141-145)
I20260812 06:17:49.921422 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000030 (ops 146-150)
I20260812 06:17:49.921453 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000031 (ops 151-155)
I20260812 06:17:49.921484 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000032 (ops 156-160)
I20260812 06:17:49.921514 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000033 (ops 161-164)
I20260812 06:17:49.921545 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000034 (ops 165-169)
I20260812 06:17:49.921574 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000035 (ops 170-174)
I20260812 06:17:49.921605 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000036 (ops 175-178)
I20260812 06:17:49.921635 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000037 (ops 179-183)
I20260812 06:17:49.921665 12060 log.cc:1079] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/680e4ec5972942b9bbe67c23ccfdb020/wal-000000038 (ops 184-188)
I20260812 06:17:49.944229 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: LogGCOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:17:49.944665 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:49.961808 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.017s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.962334 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=2.188937
I20260812 06:17:49.974468 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.974922 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=1.000000
I20260812 06:17:50.189577 11839 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.513s	user 1.681s	sys 0.095s
I20260812 06:17:50.201237 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: MajorDeltaCompactionOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.226s	user 0.147s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":289,"lbm_read_time_us":14205,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35380,"lbm_writes_lt_1ms":743,"mutex_wait_us":66,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:17:50.201803 12177 maintenance_manager.cc:419] P 1ca8475a17b64b1496d3eb3a964778c7: Scheduling FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020): perf score=18.063937
I20260812 06:17:50.243692 11839 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.001s	sys 0.000s
I20260812 06:17:50.244424 11839 tablet_server.cc:179] TabletServer@127.11.143.193:0 shutting down...
I20260812 06:17:50.248243 12060 maintenance_manager.cc:643] P 1ca8475a17b64b1496d3eb3a964778c7: FlushDeltaMemStoresOp(680e4ec5972942b9bbe67c23ccfdb020) complete. Timing: real 0.046s	user 0.037s	sys 0.007s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":19044,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:50.248723 11839 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:50.249112 11839 tablet_replica.cc:333] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7: stopping tablet replica
I20260812 06:17:50.249323 11839 raft_consensus.cc:2243] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.249512 11839 raft_consensus.cc:2272] T 680e4ec5972942b9bbe67c23ccfdb020 P 1ca8475a17b64b1496d3eb3a964778c7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.265065 11839 tablet_server.cc:196] TabletServer@127.11.143.193:0 shutdown complete.
I20260812 06:17:50.269454 11839 master.cc:562] Master@127.11.143.254:46291 shutting down...
I20260812 06:17:50.272662 11839 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.272842 11839 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.272918 11839 tablet_replica.cc:333] T 00000000000000000000000000000000 P 84552ef1a8b749a48890f2b1281f91c0: stopping tablet replica
I20260812 06:17:50.285002 11839 master.cc:584] Master@127.11.143.254:46291 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4943 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:50.357525 11839 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.143.254:38765
I20260812 06:17:50.357946 11839 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:50.359999 11839 server_base.cc:1061] running on GCE node
W20260812 06:17:50.360090 12250 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:50.360268 12245 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:50.359959 12244 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:50.360522 11839 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:50.360584 11839 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:50.360605 11839 hybrid_clock.cc:648] HybridClock initialized: now 1786515470360605 us; error 0 us; skew 500 ppm
I20260812 06:17:50.361579 11839 webserver.cc:533] Webserver started at http://127.11.143.254:41451/ using document root <none> and password file <none>
I20260812 06:17:50.361740 11839 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:50.361799 11839 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:50.361877 11839 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:50.362257 11839 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/master-0-root/instance:
uuid: "6d52b12f15ea482d8926c205a1218e9c"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-gjw7"
I20260812 06:17:50.363862 11839 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:50.364933 12257 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:50.365221 11839 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:50.365310 11839 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/master-0-root
uuid: "6d52b12f15ea482d8926c205a1218e9c"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-gjw7"
I20260812 06:17:50.365382 11839 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-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:50.378768 11839 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:50.379104 11839 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:50.382948 11839 rpc_server.cc:307] RPC server started. Bound to: 127.11.143.254:38765
I20260812 06:17:50.391179 12362 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.143.254:38765 every 8 connection(s)
I20260812 06:17:50.391964 12363 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:50.393896 12363 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c: Bootstrap starting.
I20260812 06:17:50.394680 12363 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:50.395642 12363 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c: No bootstrap required, opened a new log
I20260812 06:17:50.396037 12363 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d52b12f15ea482d8926c205a1218e9c" member_type: VOTER }
I20260812 06:17:50.396121 12363 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:50.396154 12363 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6d52b12f15ea482d8926c205a1218e9c, State: Initialized, Role: FOLLOWER
I20260812 06:17:50.396298 12363 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [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: "6d52b12f15ea482d8926c205a1218e9c" member_type: VOTER }
I20260812 06:17:50.396369 12363 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:50.396404 12363 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:50.396451 12363 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:50.397095 12363 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d52b12f15ea482d8926c205a1218e9c" member_type: VOTER }
I20260812 06:17:50.397265 12363 leader_election.cc:304] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [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: 6d52b12f15ea482d8926c205a1218e9c; no voters: 
I20260812 06:17:50.397485 12363 leader_election.cc:290] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:50.397585 12367 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:50.397771 12367 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 1 LEADER]: Becoming Leader. State: Replica: 6d52b12f15ea482d8926c205a1218e9c, State: Running, Role: LEADER
I20260812 06:17:50.397910 12363 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:50.397907 12367 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [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: "6d52b12f15ea482d8926c205a1218e9c" member_type: VOTER }
I20260812 06:17:50.398321 12368 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6d52b12f15ea482d8926c205a1218e9c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d52b12f15ea482d8926c205a1218e9c" member_type: VOTER } }
I20260812 06:17:50.398345 12369 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6d52b12f15ea482d8926c205a1218e9c. Latest consensus state: current_term: 1 leader_uuid: "6d52b12f15ea482d8926c205a1218e9c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d52b12f15ea482d8926c205a1218e9c" member_type: VOTER } }
I20260812 06:17:50.398423 12368 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:50.398432 12369 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:50.398699 12374 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:50.399453 12374 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:50.399803 11839 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:50.401062 12374 catalog_manager.cc:1383] Generated new cluster ID: cc5a82b2910d4ae9b4acc3a8ef2c4779
I20260812 06:17:50.401113 12374 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:50.410722 12374 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:50.411211 12374 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:50.416426 12374 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c: Generated new TSK 0
I20260812 06:17:50.416563 12374 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:50.432051 11839 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:50.434110 12404 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:50.434077 12399 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:50.434084 12402 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:50.434146 11839 server_base.cc:1061] running on GCE node
I20260812 06:17:50.434459 11839 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:50.434501 11839 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:50.434515 11839 hybrid_clock.cc:648] HybridClock initialized: now 1786515470434515 us; error 0 us; skew 500 ppm
I20260812 06:17:50.435355 11839 webserver.cc:533] Webserver started at http://127.11.143.193:36975/ using document root <none> and password file <none>
I20260812 06:17:50.435513 11839 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:50.435567 11839 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:50.435645 11839 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:50.436038 11839 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/instance:
uuid: "585c85b862104d91a75ace72e8742624"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-gjw7"
I20260812 06:17:50.437528 11839 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:50.438436 12409 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:50.438633 11839 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:50.438699 11839 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root
uuid: "585c85b862104d91a75ace72e8742624"
format_stamp: "Formatted at 2026-08-12 06:17:50 on dist-test-slave-gjw7"
I20260812 06:17:50.438781 11839 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-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:50.446228 11839 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:50.446573 11839 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:50.446841 11839 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:50.447265 11839 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:50.447311 11839 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:50.447346 11839 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:50.447373 11839 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:50.451399 11839 rpc_server.cc:307] RPC server started. Bound to: 127.11.143.193:38501
I20260812 06:17:50.451428 12540 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.143.193:38501 every 8 connection(s)
I20260812 06:17:50.459594 12542 heartbeater.cc:344] Connected to a master server at 127.11.143.254:38765
I20260812 06:17:50.459697 12542 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:50.459913 12542 heartbeater.cc:507] Master 127.11.143.254:38765 requested a full tablet report, sending...
I20260812 06:17:50.460496 12293 ts_manager.cc:194] Registered new tserver with Master: 585c85b862104d91a75ace72e8742624 (127.11.143.193:38501)
I20260812 06:17:50.460594 11839 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008801166s
I20260812 06:17:50.461468 12293 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38618
I20260812 06:17:50.467386 12293 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38622:
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:50.475306 12466 tablet_service.cc:1511] Processing CreateTablet for tablet 87cac8bc711d4437a01e2ecd9ad1efb2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1d5cb5bd5b6245f091bc7779f4b1ebd9]), partition=
I20260812 06:17:50.475551 12466 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 87cac8bc711d4437a01e2ecd9ad1efb2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:50.477463 12573 tablet_bootstrap.cc:492] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Bootstrap starting.
I20260812 06:17:50.478288 12573 tablet_bootstrap.cc:654] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:50.479187 12573 tablet_bootstrap.cc:492] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: No bootstrap required, opened a new log
I20260812 06:17:50.479257 12573 ts_tablet_manager.cc:1403] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:50.479573 12573 raft_consensus.cc:359] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "585c85b862104d91a75ace72e8742624" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 38501 } }
I20260812 06:17:50.479655 12573 raft_consensus.cc:385] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:50.479676 12573 raft_consensus.cc:740] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 585c85b862104d91a75ace72e8742624, State: Initialized, Role: FOLLOWER
I20260812 06:17:50.479776 12573 consensus_queue.cc:260] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [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: "585c85b862104d91a75ace72e8742624" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 38501 } }
I20260812 06:17:50.479859 12573 raft_consensus.cc:399] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:50.479898 12573 raft_consensus.cc:493] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:50.479928 12573 raft_consensus.cc:3060] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:50.480594 12573 raft_consensus.cc:515] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "585c85b862104d91a75ace72e8742624" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 38501 } }
I20260812 06:17:50.480747 12573 leader_election.cc:304] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [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: 585c85b862104d91a75ace72e8742624; no voters: 
I20260812 06:17:50.480958 12573 leader_election.cc:290] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:50.481055 12576 raft_consensus.cc:2804] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:50.481216 12576 raft_consensus.cc:697] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 1 LEADER]: Becoming Leader. State: Replica: 585c85b862104d91a75ace72e8742624, State: Running, Role: LEADER
I20260812 06:17:50.481269 12573 ts_tablet_manager.cc:1434] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:50.481383 12576 consensus_queue.cc:237] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [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: "585c85b862104d91a75ace72e8742624" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 38501 } }
I20260812 06:17:50.481482 12542 heartbeater.cc:499] Master 127.11.143.254:38765 was elected leader, sending a full tablet report...
I20260812 06:17:50.482726 12293 catalog_manager.cc:5719] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 reported cstate change: term changed from 0 to 1, leader changed from <none> to 585c85b862104d91a75ace72e8742624 (127.11.143.193). New cstate: current_term: 1 leader_uuid: "585c85b862104d91a75ace72e8742624" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "585c85b862104d91a75ace72e8742624" member_type: VOTER last_known_addr { host: "127.11.143.193" port: 38501 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:50.534305 11839 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.017s	sys 0.004s
I20260812 06:17:50.702540 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=23.023690
I20260812 06:17:50.865252 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.162s	user 0.095s	sys 0.062s Metrics: {"bytes_written":13415137,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":951,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39620,"lbm_writes_lt_1ms":884,"mutex_wait_us":791,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1635}
I20260812 06:17:50.865922 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): free 20743880 bytes of WAL
I20260812 06:17:50.866125 12419 log_reader.cc:385] T 87cac8bc711d4437a01e2ecd9ad1efb2: removed 2 log segments from log reader
I20260812 06:17:50.866201 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000001 (ops 1-6)
I20260812 06:17:50.866287 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000002 (ops 7-11)
I20260812 06:17:50.869771 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:50.870217 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:50.890152 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.020s	user 0.001s	sys 0.010s Metrics: {"bytes_written":3405234,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:17:50.890571 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:50.899399 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3173,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.899788 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:51.058971 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.159s	user 0.118s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815771,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":463,"lbm_read_time_us":12057,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25865,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":292,"threads_started":5,"update_count":2500}
I20260812 06:17:51.059509 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:51.108482 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.049s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18715,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.108953 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:51.118516 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.119114 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:51.257805 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.138s	user 0.101s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":136,"lbm_read_time_us":9322,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24634,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":48640,"update_count":2500}
I20260812 06:17:51.258865 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=12.110812
I20260812 06:17:51.305629 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.047s	user 0.031s	sys 0.012s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":19994,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:17:51.306098 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): 20513815 bytes on disk
I20260812 06:17:51.306509 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:51.306959 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:51.330303 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.023s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3200109,"delete_count":0,"lbm_write_time_us":5079,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:17:51.330780 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:51.340790 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3538,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:51.341387 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:51.509274 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.168s	user 0.126s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815774,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":426,"lbm_read_time_us":13359,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24343,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:17:51.509897 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:51.553767 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18734,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.554278 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:51.703701 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.149s	user 0.103s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":173,"lbm_read_time_us":10401,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22457,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:17:51.704200 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:51.750510 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.046s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18161,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.750982 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:51.760921 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3696,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.761483 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:51.936803 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.175s	user 0.110s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":98,"lbm_read_time_us":9407,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29786,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":50048,"update_count":2500}
I20260812 06:17:51.937362 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:51.986063 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.049s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18461,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.986634 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:51.996824 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.997489 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:52.024382 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":713,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":1259,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1406,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:52.024986 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): free 120100331 bytes of WAL
I20260812 06:17:52.025203 12419 log_reader.cc:385] T 87cac8bc711d4437a01e2ecd9ad1efb2: removed 12 log segments from log reader
I20260812 06:17:52.025260 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000003 (ops 12-16)
I20260812 06:17:52.025323 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000004 (ops 17-20)
I20260812 06:17:52.025357 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000005 (ops 21-25)
I20260812 06:17:52.025378 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000006 (ops 26-30)
I20260812 06:17:52.025408 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000007 (ops 31-35)
I20260812 06:17:52.025439 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000008 (ops 36-40)
I20260812 06:17:52.025470 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000009 (ops 41-44)
I20260812 06:17:52.025496 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000010 (ops 45-49)
I20260812 06:17:52.025523 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000011 (ops 50-54)
I20260812 06:17:52.025552 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000012 (ops 55-59)
I20260812 06:17:52.025581 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000013 (ops 60-64)
I20260812 06:17:52.025619 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000014 (ops 65-68)
I20260812 06:17:52.050160 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:52.050529 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): 462 bytes on disk
I20260812 06:17:52.050907 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.051363 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=3.181125
I20260812 06:17:52.070670 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.019s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3815,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:52.071105 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:52.080062 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3355,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.080430 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:52.308756 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.228s	user 0.128s	sys 0.093s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2615,"lbm_read_time_us":15895,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36443,"lbm_writes_lt_1ms":743,"mutex_wait_us":51,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:17:52.309837 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=17.071750
I20260812 06:17:52.368356 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.058s	user 0.038s	sys 0.004s Metrics: {"bytes_written":18748275,"delete_count":0,"lbm_write_time_us":19591,"lbm_writes_lt_1ms":460,"reinsert_count":0,"update_count":2285}
I20260812 06:17:52.368846 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=4.173312
I20260812 06:17:52.384313 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":5866711,"delete_count":0,"lbm_write_time_us":5973,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:17:52.384948 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:52.590281 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.205s	user 0.134s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":13337,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34244,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":3000}
I20260812 06:17:52.591274 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=16.079562
I20260812 06:17:52.631222 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":17681657,"delete_count":0,"lbm_write_time_us":17816,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:17:52.631762 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:52.654210 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.022s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:52.654734 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:52.664368 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.005s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3614,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.664866 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:52.854645 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.190s	user 0.114s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918191,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":268,"lbm_read_time_us":13815,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30945,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:17:52.855176 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:52.894428 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.039s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16923,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.895031 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:52.911993 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.912452 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:53.073673 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.161s	user 0.110s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":505,"lbm_read_time_us":10314,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24859,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:17:53.074314 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=15.087375
I20260812 06:17:53.114485 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.040s	user 0.014s	sys 0.024s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":17710,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:53.115012 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:53.138536 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.023s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.139004 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:53.148687 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.149107 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:53.326122 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.177s	user 0.100s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918200,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1083,"lbm_read_time_us":11794,"lbm_reads_lt_1ms":673,"lbm_write_time_us":27339,"lbm_writes_lt_1ms":643,"mutex_wait_us":507,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:17:53.326726 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:53.373908 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.047s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.374413 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:53.384472 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.384943 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:53.416273 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.031s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1106,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1564,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:53.416908 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): free 121006448 bytes of WAL
I20260812 06:17:53.417124 12419 log_reader.cc:385] T 87cac8bc711d4437a01e2ecd9ad1efb2: removed 12 log segments from log reader
I20260812 06:17:53.417223 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000015 (ops 69-73)
I20260812 06:17:53.417276 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000016 (ops 74-78)
I20260812 06:17:53.417348 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000017 (ops 79-83)
I20260812 06:17:53.417383 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000018 (ops 84-88)
I20260812 06:17:53.417416 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000019 (ops 89-92)
I20260812 06:17:53.417449 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000020 (ops 93-97)
I20260812 06:17:53.417481 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000021 (ops 98-102)
I20260812 06:17:53.417514 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000022 (ops 103-107)
I20260812 06:17:53.417546 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000023 (ops 108-112)
I20260812 06:17:53.417579 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000024 (ops 113-117)
I20260812 06:17:53.417611 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000025 (ops 118-122)
I20260812 06:17:53.417644 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000026 (ops 123-127)
I20260812 06:17:53.437245 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {}
I20260812 06:17:53.437657 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:53.460780 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.023s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.461266 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:53.471091 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.471638 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): 472 bytes on disk
I20260812 06:17:53.472069 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:53.472584 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:53.672996 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.200s	user 0.134s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020747,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2315,"lbm_read_time_us":15677,"lbm_reads_lt_1ms":774,"lbm_write_time_us":31932,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9216,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:17:53.673731 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=18.063937
I20260812 06:17:53.738561 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.065s	user 0.035s	sys 0.027s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26881,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:17:53.738996 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=3.181125
I20260812 06:17:53.754861 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.016s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:53.755283 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:53.764063 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3268,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.764460 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:53.950129 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.186s	user 0.148s	sys 0.036s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020621,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":127,"lbm_read_time_us":13637,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37221,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3500}
I20260812 06:17:53.950778 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:54.014252 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.063s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25042,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.016506 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=3.181125
I20260812 06:17:54.033470 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.016s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:54.033910 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:54.047055 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4767,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.047598 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:54.205603 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.158s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":571,"lbm_read_time_us":12414,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30652,"lbm_writes_lt_1ms":643,"mutex_wait_us":345,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":148224,"update_count":3000}
I20260812 06:17:54.206184 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:54.252555 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.046s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19509,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.253082 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:54.267819 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.268433 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:54.421511 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.152s	user 0.127s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":9853,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28360,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:54.422273 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=13.103000
I20260812 06:17:54.465644 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.043s	user 0.012s	sys 0.029s Metrics: {"bytes_written":14604841,"delete_count":0,"lbm_write_time_us":19412,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":358,"reinsert_count":0,"update_count":1780}
I20260812 06:17:54.466113 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.196750
I20260812 06:17:54.476826 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.011s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2215508,"delete_count":0,"lbm_write_time_us":1910,"lbm_writes_lt_1ms":57,"reinsert_count":0,"update_count":270}
I20260812 06:17:54.477362 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:54.490363 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4673,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.490917 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:54.646977 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.156s	user 0.107s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":192,"lbm_read_time_us":10496,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25519,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:17:54.647634 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:54.696290 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.048s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.696795 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:54.707211 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.707710 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:54.737890 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushMRSOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":326,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1126,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1428,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:54.738536 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): free 133024597 bytes of WAL
I20260812 06:17:54.738755 12419 log_reader.cc:385] T 87cac8bc711d4437a01e2ecd9ad1efb2: removed 13 log segments from log reader
I20260812 06:17:54.738804 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000027 (ops 128-132)
I20260812 06:17:54.738840 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000028 (ops 133-137)
I20260812 06:17:54.738871 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000029 (ops 138-142)
I20260812 06:17:54.738902 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000030 (ops 143-147)
I20260812 06:17:54.738934 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000031 (ops 148-152)
I20260812 06:17:54.738965 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000032 (ops 153-157)
I20260812 06:17:54.738996 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000033 (ops 158-162)
I20260812 06:17:54.739024 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000034 (ops 163-167)
I20260812 06:17:54.739053 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000035 (ops 168-172)
I20260812 06:17:54.739084 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000036 (ops 173-177)
I20260812 06:17:54.739112 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000037 (ops 178-182)
I20260812 06:17:54.739142 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000038 (ops 183-186)
I20260812 06:17:54.739172 12419 log.cc:1079] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: Deleting log segment in path: /tmp/dist-test-taskqPndDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515465403815-11839-0/minicluster-data/ts-0-root/wals/87cac8bc711d4437a01e2ecd9ad1efb2/wal-000000039 (ops 187-191)
I20260812 06:17:54.763659 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: LogGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:54.764472 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2): 472 bytes on disk
I20260812 06:17:54.765014 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: UndoDeltaBlockGCOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.765596 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=3.181125
I20260812 06:17:54.777789 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:54.778196 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=2.188937
I20260812 06:17:54.787451 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3494,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.787969 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:54.956984 11839 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.423s	user 1.639s	sys 0.133s
I20260812 06:17:54.976354 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.188s	user 0.143s	sys 0.043s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":13989,"lbm_reads_lt_1ms":770,"lbm_write_time_us":33895,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3500}
I20260812 06:17:54.976925 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=14.095187
I20260812 06:17:55.006501 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: FlushDeltaMemStoresOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.029s	user 0.018s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":13615,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:17:55.007124 12543 maintenance_manager.cc:419] P 585c85b862104d91a75ace72e8742624: Scheduling MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2): perf score=1.000000
I20260812 06:17:55.034174 11839 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.002s	sys 0.000s
I20260812 06:17:55.034720 11839 tablet_server.cc:179] TabletServer@127.11.143.193:0 shutting down...
I20260812 06:17:55.114789 12419 maintenance_manager.cc:643] P 585c85b862104d91a75ace72e8742624: MajorDeltaCompactionOp(87cac8bc711d4437a01e2ecd9ad1efb2) complete. Timing: real 0.107s	user 0.081s	sys 0.026s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":394,"lbm_read_time_us":8066,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21613,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:55.115437 11839 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:55.115661 11839 tablet_replica.cc:333] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624: stopping tablet replica
I20260812 06:17:55.115784 11839 raft_consensus.cc:2243] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:55.115945 11839 raft_consensus.cc:2272] T 87cac8bc711d4437a01e2ecd9ad1efb2 P 585c85b862104d91a75ace72e8742624 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:55.129855 11839 tablet_server.cc:196] TabletServer@127.11.143.193:0 shutdown complete.
I20260812 06:17:55.156463 11839 master.cc:562] Master@127.11.143.254:38765 shutting down...
I20260812 06:17:55.159341 11839 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:55.159502 11839 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:55.159571 11839 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6d52b12f15ea482d8926c205a1218e9c: stopping tablet replica
I20260812 06:17:55.171644 11839 master.cc:584] Master@127.11.143.254:38765 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4883 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9827 ms total)

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