[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:24.304888 30277 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.145.126:32839
I20260812 06:18:24.305889 30277 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:24.306485 30277 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.312569 30286 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:18:24.312574 30288 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:18:24.312745 30277 server_base.cc:1061] running on GCE node
W20260812 06:18:24.312915 30285 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:24.313414 30277 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.313537 30277 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:24.313581 30277 hybrid_clock.cc:648] HybridClock initialized: now 1786515504313579 us; error 0 us; skew 500 ppm
I20260812 06:18:24.315227 30277 webserver.cc:533] Webserver started at http://127.29.145.126:33859/ using document root <none> and password file <none>
I20260812 06:18:24.315762 30277 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.315850 30277 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.316160 30277 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.317796 30277 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/master-0-root/instance:
uuid: "e2e0288e031142a199f451516bbdd65b"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-t3q3"
I20260812 06:18:24.321332 30277 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:24.323372 30298 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:18:24.324399 30277 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:24.324543 30277 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/master-0-root
uuid: "e2e0288e031142a199f451516bbdd65b"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-t3q3"
I20260812 06:18:24.324659 30277 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-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:18:24.343151 30277 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.343853 30277 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:18:24.344054 30277 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:24.352370 30277 rpc_server.cc:307] RPC server started. Bound to: 127.29.145.126:32839
I20260812 06:18:24.352376 30384 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.145.126:32839 every 8 connection(s)
I20260812 06:18:24.354744 30385 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:18:24.360138 30385 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: Bootstrap starting.
I20260812 06:18:24.362566 30385 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:24.363430 30385 log.cc:826] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:24.365120 30385 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: No bootstrap required, opened a new log
I20260812 06:18:24.367877 30385 raft_consensus.cc:359] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2e0288e031142a199f451516bbdd65b" member_type: VOTER }
I20260812 06:18:24.368041 30385 raft_consensus.cc:385] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:24.368145 30385 raft_consensus.cc:740] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e2e0288e031142a199f451516bbdd65b, State: Initialized, Role: FOLLOWER
I20260812 06:18:24.368721 30385 consensus_queue.cc:260] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [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: "e2e0288e031142a199f451516bbdd65b" member_type: VOTER }
I20260812 06:18:24.368854 30385 raft_consensus.cc:399] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:24.368901 30385 raft_consensus.cc:493] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:24.368991 30385 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:24.369750 30385 raft_consensus.cc:515] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2e0288e031142a199f451516bbdd65b" member_type: VOTER }
I20260812 06:18:24.370139 30385 leader_election.cc:304] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [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: e2e0288e031142a199f451516bbdd65b; no voters: 
I20260812 06:18:24.370405 30385 leader_election.cc:290] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:24.370554 30391 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:24.370841 30391 raft_consensus.cc:697] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 1 LEADER]: Becoming Leader. State: Replica: e2e0288e031142a199f451516bbdd65b, State: Running, Role: LEADER
I20260812 06:18:24.371270 30391 consensus_queue.cc:237] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [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: "e2e0288e031142a199f451516bbdd65b" member_type: VOTER }
I20260812 06:18:24.371501 30385 sys_catalog.cc:565] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:24.373340 30395 sys_catalog.cc:455] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [sys.catalog]: SysCatalogTable state changed. Reason: New leader e2e0288e031142a199f451516bbdd65b. Latest consensus state: current_term: 1 leader_uuid: "e2e0288e031142a199f451516bbdd65b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2e0288e031142a199f451516bbdd65b" member_type: VOTER } }
I20260812 06:18:24.373363 30392 sys_catalog.cc:455] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e2e0288e031142a199f451516bbdd65b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2e0288e031142a199f451516bbdd65b" member_type: VOTER } }
I20260812 06:18:24.373493 30395 sys_catalog.cc:458] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:24.373550 30392 sys_catalog.cc:458] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:24.373886 30277 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:24.375747 30419 catalog_manager.cc:1594] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:24.375833 30419 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:24.375900 30418 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:24.376677 30418 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:24.381507 30418 catalog_manager.cc:1383] Generated new cluster ID: 684e5e56d3394b2a9bda932e77e154df
I20260812 06:18:24.381577 30418 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:24.392935 30418 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:24.393783 30418 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:24.402951 30418 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: Generated new TSK 0
I20260812 06:18:24.403569 30418 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:24.406416 30277 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.409271 30428 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:18:24.409374 30426 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:24.409416 30277 server_base.cc:1061] running on GCE node
W20260812 06:18:24.409320 30430 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:18:24.409986 30277 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.410065 30277 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:24.410104 30277 hybrid_clock.cc:648] HybridClock initialized: now 1786515504410102 us; error 0 us; skew 500 ppm
I20260812 06:18:24.411085 30277 webserver.cc:533] Webserver started at http://127.29.145.65:36877/ using document root <none> and password file <none>
I20260812 06:18:24.411284 30277 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.411358 30277 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.411437 30277 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.411831 30277 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/instance:
uuid: "025d973558354f7cbcfd4b86844ef069"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-t3q3"
I20260812 06:18:24.413452 30277 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:24.414547 30436 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:18:24.414799 30277 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:24.414873 30277 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root
uuid: "025d973558354f7cbcfd4b86844ef069"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-t3q3"
I20260812 06:18:24.414964 30277 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-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:18:24.424718 30277 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.425165 30277 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:24.425714 30277 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:24.426615 30277 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:24.426671 30277 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.426735 30277 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:24.426781 30277 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.433779 30277 rpc_server.cc:307] RPC server started. Bound to: 127.29.145.65:40121
I20260812 06:18:24.433863 30539 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.145.65:40121 every 8 connection(s)
I20260812 06:18:24.447309 30540 heartbeater.cc:344] Connected to a master server at 127.29.145.126:32839
I20260812 06:18:24.447572 30540 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:24.448097 30540 heartbeater.cc:507] Master 127.29.145.126:32839 requested a full tablet report, sending...
I20260812 06:18:24.449865 30329 ts_manager.cc:194] Registered new tserver with Master: 025d973558354f7cbcfd4b86844ef069 (127.29.145.65:40121)
I20260812 06:18:24.450115 30277 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015647841s
I20260812 06:18:24.451174 30329 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56328
I20260812 06:18:24.459776 30329 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56330:
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:18:24.474268 30483 tablet_service.cc:1511] Processing CreateTablet for tablet c8cbbd67ef0f4d80b1f631a08103699f (DEFAULT_TABLE table=heavy-update-compaction-test [id=cc1e178feeb94d308022bbdcb2924897]), partition=
I20260812 06:18:24.474723 30483 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c8cbbd67ef0f4d80b1f631a08103699f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:24.481498 30560 tablet_bootstrap.cc:492] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Bootstrap starting.
I20260812 06:18:24.485363 30560 tablet_bootstrap.cc:654] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:24.486946 30560 tablet_bootstrap.cc:492] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: No bootstrap required, opened a new log
I20260812 06:18:24.487082 30560 ts_tablet_manager.cc:1403] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Time spent bootstrapping tablet: real 0.006s	user 0.002s	sys 0.000s
I20260812 06:18:24.487553 30560 raft_consensus.cc:359] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "025d973558354f7cbcfd4b86844ef069" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 40121 } }
I20260812 06:18:24.487692 30560 raft_consensus.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:24.487756 30560 raft_consensus.cc:740] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 025d973558354f7cbcfd4b86844ef069, State: Initialized, Role: FOLLOWER
I20260812 06:18:24.487926 30560 consensus_queue.cc:260] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [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: "025d973558354f7cbcfd4b86844ef069" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 40121 } }
I20260812 06:18:24.488047 30560 raft_consensus.cc:399] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:24.488119 30560 raft_consensus.cc:493] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:24.488179 30560 raft_consensus.cc:3060] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:24.488911 30560 raft_consensus.cc:515] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "025d973558354f7cbcfd4b86844ef069" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 40121 } }
I20260812 06:18:24.489071 30560 leader_election.cc:304] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [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: 025d973558354f7cbcfd4b86844ef069; no voters: 
I20260812 06:18:24.489317 30560 leader_election.cc:290] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:24.489411 30569 raft_consensus.cc:2804] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:24.489643 30569 raft_consensus.cc:697] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 1 LEADER]: Becoming Leader. State: Replica: 025d973558354f7cbcfd4b86844ef069, State: Running, Role: LEADER
I20260812 06:18:24.489832 30560 ts_tablet_manager.cc:1434] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:24.490047 30540 heartbeater.cc:499] Master 127.29.145.126:32839 was elected leader, sending a full tablet report...
I20260812 06:18:24.489837 30569 consensus_queue.cc:237] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [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: "025d973558354f7cbcfd4b86844ef069" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 40121 } }
I20260812 06:18:24.493268 30329 catalog_manager.cc:5719] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 reported cstate change: term changed from 0 to 1, leader changed from <none> to 025d973558354f7cbcfd4b86844ef069 (127.29.145.65). New cstate: current_term: 1 leader_uuid: "025d973558354f7cbcfd4b86844ef069" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "025d973558354f7cbcfd4b86844ef069" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 40121 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:24.560470 30277 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.023s	sys 0.004s
I20260812 06:18:24.685103 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=15.086190
I20260812 06:18:24.852239 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.167s	user 0.109s	sys 0.053s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":268,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":861,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40052,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":124,"threads_started":1,"update_count":1500}
I20260812 06:18:24.853463 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 11976772 bytes of WAL
I20260812 06:18:24.853775 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 1 log segments from log reader
I20260812 06:18:24.853835 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000001 (ops 1-6)
I20260812 06:18:24.856940 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:24.857264 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=4.173312
I20260812 06:18:24.875422 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":7354,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:18:24.875890 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.196750
I20260812 06:18:24.886430 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:24.886955 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f): 12308958 bytes on disk
I20260812 06:18:24.887610 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.888224 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:25.071213 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.183s	user 0.102s	sys 0.066s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733816,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":929,"lbm_read_time_us":11927,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26527,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":340,"threads_started":5,"update_count":2500}
I20260812 06:18:25.071805 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:25.131791 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.060s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27691,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.132324 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:25.148411 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.148953 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:25.305274 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.156s	user 0.105s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":827,"lbm_read_time_us":9374,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30709,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:25.306023 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:25.363914 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.058s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":25182,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.364528 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:25.375425 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.376161 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:25.527331 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.151s	user 0.122s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733728,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":11514,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31483,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:18:25.528158 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=10.126437
I20260812 06:18:25.571288 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.043s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15210,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.571977 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:25.583979 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.584555 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:25.706427 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.122s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":8966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23942,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:25.707123 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=10.126437
I20260812 06:18:25.754335 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.047s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16922,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.754963 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:25.771901 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.772493 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:25.918026 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.145s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":11695,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22823,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:25.918963 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=10.126437
I20260812 06:18:25.956245 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.037s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.956736 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:25.975606 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.019s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.976104 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:25.999857 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.024s	user 0.022s	sys 0.001s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1130,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1332,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:26.000696 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 112239317 bytes of WAL
I20260812 06:18:26.000926 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 11 log segments from log reader
I20260812 06:18:26.000970 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000002 (ops 7-11)
I20260812 06:18:26.000998 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000003 (ops 12-16)
I20260812 06:18:26.001015 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000004 (ops 17-21)
I20260812 06:18:26.001066 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000005 (ops 22-26)
I20260812 06:18:26.001102 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000006 (ops 27-31)
I20260812 06:18:26.001163 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000007 (ops 32-36)
I20260812 06:18:26.001204 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000008 (ops 37-40)
I20260812 06:18:26.001241 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000009 (ops 41-45)
I20260812 06:18:26.001279 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000010 (ops 46-50)
I20260812 06:18:26.001314 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000011 (ops 51-55)
I20260812 06:18:26.001351 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000012 (ops 56-60)
I20260812 06:18:26.027189 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:26.027770 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=4.173312
I20260812 06:18:26.050886 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":6071825,"delete_count":0,"lbm_write_time_us":5717,"lbm_writes_lt_1ms":151,"reinsert_count":0,"update_count":740}
I20260812 06:18:26.051337 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 8767116 bytes of WAL
I20260812 06:18:26.051499 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 1 log segments from log reader
I20260812 06:18:26.051528 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000013 (ops 61-65)
I20260812 06:18:26.053865 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:26.054164 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:26.061537 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.007s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2133453,"delete_count":0,"lbm_write_time_us":2603,"lbm_writes_lt_1ms":55,"reinsert_count":0,"update_count":260}
I20260812 06:18:26.061910 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f): 447 bytes on disk
I20260812 06:18:26.062304 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.062701 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:26.280385 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.218s	user 0.137s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":552,"lbm_read_time_us":15409,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37515,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:26.280998 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:26.339824 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.059s	user 0.042s	sys 0.013s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21238,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.340447 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:26.353124 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.353582 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:26.527278 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.174s	user 0.126s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":11666,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28212,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:26.527906 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:26.576735 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.049s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22774,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.577337 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:26.597702 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.020s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.598284 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:26.782197 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.184s	user 0.111s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1158,"lbm_read_time_us":12015,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31634,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:26.782682 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:26.836620 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.054s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24735,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.837085 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:26.848913 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.849541 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:27.034512 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.185s	user 0.099s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":957,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30355,"lbm_writes_lt_1ms":543,"mutex_wait_us":360,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:18:27.035115 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:27.086922 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.052s	user 0.015s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20381,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.087491 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:27.103122 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.103636 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:27.264262 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.160s	user 0.117s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1637,"lbm_read_time_us":11299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30076,"lbm_writes_lt_1ms":543,"mutex_wait_us":580,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:27.266146 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=11.118625
I20260812 06:18:27.301018 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.035s	user 0.026s	sys 0.007s Metrics: {"bytes_written":13538210,"delete_count":0,"lbm_write_time_us":15672,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:18:27.303469 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.196750
I20260812 06:18:27.321605 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.018s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3302,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:18:27.322106 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:27.332691 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.333161 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:27.489791 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.156s	user 0.115s	sys 0.034s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":585,"lbm_read_time_us":11285,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30207,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73088,"update_count":2500}
I20260812 06:18:27.490429 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:27.543573 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.053s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22998,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.544221 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:27.563493 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.563988 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:27.614212 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.050s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":1453,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2477,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:27.614912 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 124257264 bytes of WAL
I20260812 06:18:27.615178 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 12 log segments from log reader
I20260812 06:18:27.615224 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000014 (ops 66-70)
I20260812 06:18:27.615278 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000015 (ops 71-75)
I20260812 06:18:27.615320 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000016 (ops 76-80)
I20260812 06:18:27.615384 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000017 (ops 81-85)
I20260812 06:18:27.615427 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000018 (ops 86-90)
I20260812 06:18:27.615466 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000019 (ops 91-95)
I20260812 06:18:27.615509 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000020 (ops 96-100)
I20260812 06:18:27.615551 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000021 (ops 101-105)
I20260812 06:18:27.615579 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000022 (ops 106-110)
I20260812 06:18:27.615617 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000023 (ops 111-114)
I20260812 06:18:27.615659 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000024 (ops 115-119)
I20260812 06:18:27.615700 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000025 (ops 120-124)
I20260812 06:18:27.643282 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:27.643731 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f): 493 bytes on disk
I20260812 06:18:27.644326 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f) 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:18:27.644863 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=7.149875
I20260812 06:18:27.676576 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.032s	user 0.016s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8871,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:27.677192 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 8767120 bytes of WAL
I20260812 06:18:27.677465 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 1 log segments from log reader
I20260812 06:18:27.677534 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000026 (ops 125-129)
I20260812 06:18:27.680260 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:27.680828 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:27.698562 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.018s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.699090 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:27.953850 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.254s	user 0.186s	sys 0.067s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37041189,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":668,"lbm_read_time_us":17834,"lbm_reads_lt_1ms":866,"lbm_write_time_us":44915,"lbm_writes_lt_1ms":843,"mutex_wait_us":335,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":35200,"thread_start_us":92,"threads_started":1,"update_count":4000}
I20260812 06:18:27.954773 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=18.063937
I20260812 06:18:28.022732 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.068s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26729,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:28.023428 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:28.034476 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.034955 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:28.247803 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.213s	user 0.128s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":13046,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35424,"lbm_writes_lt_1ms":643,"mutex_wait_us":99,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":3000}
I20260812 06:18:28.248621 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=16.079562
I20260812 06:18:28.294680 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.046s	user 0.026s	sys 0.015s Metrics: {"bytes_written":17681654,"delete_count":0,"lbm_write_time_us":19678,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:18:28.295323 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:28.314860 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.019s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:28.315441 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:28.325320 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.325784 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:28.521871 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.196s	user 0.136s	sys 0.059s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836228,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":133,"lbm_read_time_us":13419,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31774,"lbm_writes_lt_1ms":643,"mutex_wait_us":90,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:18:28.522673 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:28.569283 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20917,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.569844 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:28.583619 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5049,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.584223 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:28.753978 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.170s	user 0.136s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":11048,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28970,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:18:28.756559 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:28.809121 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.052s	user 0.047s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23121,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.809707 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:28.825016 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.825584 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:29.003551 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.178s	user 0.137s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1227,"lbm_read_time_us":11088,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32405,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:29.004228 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=14.095187
I20260812 06:18:29.071036 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.067s	user 0.043s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25775,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.071554 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=3.181125
I20260812 06:18:29.086390 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4421,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:29.086956 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:29.096755 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3712,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.097362 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:29.133159 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushMRSOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.036s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1330,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1622,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:29.133894 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 116849781 bytes of WAL
I20260812 06:18:29.134150 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 12 log segments from log reader
I20260812 06:18:29.134195 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000027 (ops 130-134)
I20260812 06:18:29.134223 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000028 (ops 135-139)
I20260812 06:18:29.134264 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000029 (ops 140-144)
I20260812 06:18:29.134315 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000030 (ops 145-148)
I20260812 06:18:29.134334 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000031 (ops 149-153)
I20260812 06:18:29.134390 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000032 (ops 154-158)
I20260812 06:18:29.134441 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000033 (ops 159-162)
I20260812 06:18:29.134479 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000034 (ops 163-167)
I20260812 06:18:29.134542 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000035 (ops 168-172)
I20260812 06:18:29.134581 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000036 (ops 173-176)
I20260812 06:18:29.134620 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000037 (ops 177-181)
I20260812 06:18:29.134661 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000038 (ops 182-186)
I20260812 06:18:29.159590 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:29.160152 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f): 472 bytes on disk
I20260812 06:18:29.160740 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: UndoDeltaBlockGCOp(c8cbbd67ef0f4d80b1f631a08103699f) 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:18:29.161445 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:29.182924 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.021s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.183434 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f): free 11564891 bytes of WAL
I20260812 06:18:29.183648 30444 log_reader.cc:385] T c8cbbd67ef0f4d80b1f631a08103699f: removed 1 log segments from log reader
I20260812 06:18:29.183691 30444 log.cc:1079] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/c8cbbd67ef0f4d80b1f631a08103699f/wal-000000039 (ops 187-190)
I20260812 06:18:29.186089 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: LogGCOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:29.186447 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=2.188937
I20260812 06:18:29.199411 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.013s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.199873 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=1.000000
I20260812 06:18:29.437222 30277 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.877s	user 1.817s	sys 0.114s
I20260812 06:18:29.442797 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: MajorDeltaCompactionOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.243s	user 0.167s	sys 0.076s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37041307,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":764,"lbm_read_time_us":19364,"lbm_reads_lt_1ms":871,"lbm_write_time_us":45853,"lbm_writes_lt_1ms":843,"mutex_wait_us":18,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":59520,"thread_start_us":92,"threads_started":1,"update_count":4000}
I20260812 06:18:29.447456 30541 maintenance_manager.cc:419] P 025d973558354f7cbcfd4b86844ef069: Scheduling FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f): perf score=18.063937
I20260812 06:18:29.471932 30277 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.034s	user 0.002s	sys 0.000s
I20260812 06:18:29.472797 30277 tablet_server.cc:179] TabletServer@127.29.145.65:0 shutting down...
I20260812 06:18:29.512786 30444 maintenance_manager.cc:643] P 025d973558354f7cbcfd4b86844ef069: FlushDeltaMemStoresOp(c8cbbd67ef0f4d80b1f631a08103699f) complete. Timing: real 0.065s	user 0.031s	sys 0.024s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":29533,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:29.513446 30277 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:29.513849 30277 tablet_replica.cc:333] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069: stopping tablet replica
I20260812 06:18:29.514096 30277 raft_consensus.cc:2243] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.514349 30277 raft_consensus.cc:2272] T c8cbbd67ef0f4d80b1f631a08103699f P 025d973558354f7cbcfd4b86844ef069 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.519323 30277 tablet_server.cc:196] TabletServer@127.29.145.65:0 shutdown complete.
I20260812 06:18:29.523867 30277 master.cc:562] Master@127.29.145.126:32839 shutting down...
I20260812 06:18:29.527732 30277 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.527920 30277 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.528028 30277 tablet_replica.cc:333] T 00000000000000000000000000000000 P e2e0288e031142a199f451516bbdd65b: stopping tablet replica
I20260812 06:18:29.540735 30277 master.cc:584] Master@127.29.145.126:32839 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5332 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:29.638063 30277 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.145.126:37463
I20260812 06:18:29.640007 30277 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.642300 30594 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:29.642409 30277 server_base.cc:1061] running on GCE node
W20260812 06:18:29.642584 30598 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:29.642603 30595 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:29.643241 30277 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.643308 30277 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:29.643330 30277 hybrid_clock.cc:648] HybridClock initialized: now 1786515509643329 us; error 0 us; skew 500 ppm
I20260812 06:18:29.644340 30277 webserver.cc:533] Webserver started at http://127.29.145.126:35465/ using document root <none> and password file <none>
I20260812 06:18:29.644532 30277 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.644603 30277 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.644688 30277 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.645085 30277 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/master-0-root/instance:
uuid: "79807a89faa14b8181e89b3f4533dfb2"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-t3q3"
I20260812 06:18:29.646940 30277 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:29.649142 30605 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:18:29.651501 30277 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.001s	sys 0.000s
I20260812 06:18:29.651575 30277 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/master-0-root
uuid: "79807a89faa14b8181e89b3f4533dfb2"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-t3q3"
I20260812 06:18:29.651687 30277 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-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:18:29.666877 30277 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.667404 30277 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.673189 30277 rpc_server.cc:307] RPC server started. Bound to: 127.29.145.126:37463
I20260812 06:18:29.674671 30696 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.145.126:37463 every 8 connection(s)
I20260812 06:18:29.691032 30697 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:18:29.693208 30697 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2: Bootstrap starting.
I20260812 06:18:29.693984 30697 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.694999 30697 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2: No bootstrap required, opened a new log
I20260812 06:18:29.695351 30697 raft_consensus.cc:359] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79807a89faa14b8181e89b3f4533dfb2" member_type: VOTER }
I20260812 06:18:29.695434 30697 raft_consensus.cc:385] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.695457 30697 raft_consensus.cc:740] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 79807a89faa14b8181e89b3f4533dfb2, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.695616 30697 consensus_queue.cc:260] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [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: "79807a89faa14b8181e89b3f4533dfb2" member_type: VOTER }
I20260812 06:18:29.695704 30697 raft_consensus.cc:399] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.695729 30697 raft_consensus.cc:493] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.695765 30697 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.696523 30697 raft_consensus.cc:515] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79807a89faa14b8181e89b3f4533dfb2" member_type: VOTER }
I20260812 06:18:29.696655 30697 leader_election.cc:304] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [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: 79807a89faa14b8181e89b3f4533dfb2; no voters: 
I20260812 06:18:29.696820 30697 leader_election.cc:290] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.696988 30701 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.697223 30701 raft_consensus.cc:697] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 1 LEADER]: Becoming Leader. State: Replica: 79807a89faa14b8181e89b3f4533dfb2, State: Running, Role: LEADER
I20260812 06:18:29.697315 30697 sys_catalog.cc:565] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:29.697368 30701 consensus_queue.cc:237] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [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: "79807a89faa14b8181e89b3f4533dfb2" member_type: VOTER }
I20260812 06:18:29.697862 30702 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "79807a89faa14b8181e89b3f4533dfb2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79807a89faa14b8181e89b3f4533dfb2" member_type: VOTER } }
I20260812 06:18:29.697912 30703 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 79807a89faa14b8181e89b3f4533dfb2. Latest consensus state: current_term: 1 leader_uuid: "79807a89faa14b8181e89b3f4533dfb2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79807a89faa14b8181e89b3f4533dfb2" member_type: VOTER } }
I20260812 06:18:29.698016 30703 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.697962 30702 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.698529 30710 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:29.699448 30710 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:29.699704 30277 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:29.701309 30710 catalog_manager.cc:1383] Generated new cluster ID: ae06af5e88f34c6cacdb23be0adbad58
I20260812 06:18:29.701370 30710 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:29.706811 30710 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:29.707367 30710 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:29.713995 30710 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2: Generated new TSK 0
I20260812 06:18:29.714176 30710 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:29.715811 30277 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.717917 30727 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:18:29.717943 30729 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:29.717994 30277 server_base.cc:1061] running on GCE node
W20260812 06:18:29.718083 30738 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:18:29.718360 30277 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.718407 30277 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:29.718423 30277 hybrid_clock.cc:648] HybridClock initialized: now 1786515509718423 us; error 0 us; skew 500 ppm
I20260812 06:18:29.719347 30277 webserver.cc:533] Webserver started at http://127.29.145.65:40037/ using document root <none> and password file <none>
I20260812 06:18:29.719545 30277 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.719626 30277 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.719724 30277 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.720228 30277 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/instance:
uuid: "cd18a697924a423ebc6f03ac1b0f824c"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-t3q3"
I20260812 06:18:29.721711 30277 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:29.722635 30745 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:18:29.722901 30277 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:29.722996 30277 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root
uuid: "cd18a697924a423ebc6f03ac1b0f824c"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-t3q3"
I20260812 06:18:29.723089 30277 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-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:18:29.731894 30277 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.732321 30277 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.732652 30277 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:29.733141 30277 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:29.733204 30277 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.733268 30277 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:29.733316 30277 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.737650 30277 rpc_server.cc:307] RPC server started. Bound to: 127.29.145.65:45115
I20260812 06:18:29.737686 30844 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.145.65:45115 every 8 connection(s)
I20260812 06:18:29.742991 30845 heartbeater.cc:344] Connected to a master server at 127.29.145.126:37463
I20260812 06:18:29.743113 30845 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:29.743351 30845 heartbeater.cc:507] Master 127.29.145.126:37463 requested a full tablet report, sending...
I20260812 06:18:29.744051 30633 ts_manager.cc:194] Registered new tserver with Master: cd18a697924a423ebc6f03ac1b0f824c (127.29.145.65:45115)
I20260812 06:18:29.744793 30277 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006702571s
I20260812 06:18:29.744863 30633 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57266
I20260812 06:18:29.752192 30633 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57270:
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:18:29.761305 30784 tablet_service.cc:1511] Processing CreateTablet for tablet 10ed9353f9144d3c9d93c311b2a2f8aa (DEFAULT_TABLE table=heavy-update-compaction-test [id=6dae8449eefb470cae3de8d597f06def]), partition=
I20260812 06:18:29.761626 30784 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 10ed9353f9144d3c9d93c311b2a2f8aa. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:29.763767 30863 tablet_bootstrap.cc:492] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Bootstrap starting.
I20260812 06:18:29.764705 30863 tablet_bootstrap.cc:654] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.765799 30863 tablet_bootstrap.cc:492] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: No bootstrap required, opened a new log
I20260812 06:18:29.765908 30863 ts_tablet_manager.cc:1403] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:29.766398 30863 raft_consensus.cc:359] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd18a697924a423ebc6f03ac1b0f824c" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 45115 } }
I20260812 06:18:29.766534 30863 raft_consensus.cc:385] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.766590 30863 raft_consensus.cc:740] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cd18a697924a423ebc6f03ac1b0f824c, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.766731 30863 consensus_queue.cc:260] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [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: "cd18a697924a423ebc6f03ac1b0f824c" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 45115 } }
I20260812 06:18:29.766825 30863 raft_consensus.cc:399] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.766880 30863 raft_consensus.cc:493] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.766947 30863 raft_consensus.cc:3060] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.767684 30863 raft_consensus.cc:515] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd18a697924a423ebc6f03ac1b0f824c" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 45115 } }
I20260812 06:18:29.767844 30863 leader_election.cc:304] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [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: cd18a697924a423ebc6f03ac1b0f824c; no voters: 
I20260812 06:18:29.768102 30863 leader_election.cc:290] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.768244 30865 raft_consensus.cc:2804] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.768484 30845 heartbeater.cc:499] Master 127.29.145.126:37463 was elected leader, sending a full tablet report...
I20260812 06:18:29.768465 30865 raft_consensus.cc:697] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 1 LEADER]: Becoming Leader. State: Replica: cd18a697924a423ebc6f03ac1b0f824c, State: Running, Role: LEADER
I20260812 06:18:29.768478 30863 ts_tablet_manager.cc:1434] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:29.768649 30865 consensus_queue.cc:237] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [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: "cd18a697924a423ebc6f03ac1b0f824c" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 45115 } }
I20260812 06:18:29.770018 30633 catalog_manager.cc:5719] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c reported cstate change: term changed from 0 to 1, leader changed from <none> to cd18a697924a423ebc6f03ac1b0f824c (127.29.145.65). New cstate: current_term: 1 leader_uuid: "cd18a697924a423ebc6f03ac1b0f824c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd18a697924a423ebc6f03ac1b0f824c" member_type: VOTER last_known_addr { host: "127.29.145.65" port: 45115 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:29.829742 30277 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.021s	sys 0.002s
I20260812 06:18:29.988653 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=19.054940
I20260812 06:18:30.141278 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.152s	user 0.107s	sys 0.044s Metrics: {"bytes_written":12553626,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":820,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40941,"lbm_writes_lt_1ms":773,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1530}
I20260812 06:18:30.142089 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): free 20290830 bytes of WAL
I20260812 06:18:30.142391 30750 log_reader.cc:385] T 10ed9353f9144d3c9d93c311b2a2f8aa: removed 2 log segments from log reader
I20260812 06:18:30.142494 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000001 (ops 1-6)
I20260812 06:18:30.142570 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000002 (ops 7-10)
I20260812 06:18:30.147763 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {"spinlock_wait_cycles":4992}
I20260812 06:18:30.148352 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): 16821645 bytes on disk
I20260812 06:18:30.148828 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.149359 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:30.169934 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3856511,"delete_count":0,"lbm_write_time_us":5839,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:30.170413 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:30.183903 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.184551 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:30.344372 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.160s	user 0.115s	sys 0.045s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405537,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":937,"lbm_read_time_us":12247,"lbm_reads_lt_1ms":559,"lbm_write_time_us":31325,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":378,"threads_started":5,"update_count":2450}
I20260812 06:18:30.345026 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=11.118625
I20260812 06:18:30.376513 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.031s	user 0.012s	sys 0.018s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13696,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.376961 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:30.391916 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5605,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.392419 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:30.522948 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.130s	user 0.112s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":10075,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24354,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:30.523622 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=10.126437
I20260812 06:18:30.570181 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.046s	user 0.025s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16267,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.570735 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:30.581451 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.581880 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:30.727666 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.146s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":302,"lbm_read_time_us":11376,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24707,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:18:30.728355 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=10.126437
I20260812 06:18:30.769312 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.041s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16658,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.769902 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:30.781435 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.782124 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:30.905145 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.123s	user 0.107s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":931,"lbm_read_time_us":9408,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22724,"lbm_writes_lt_1ms":443,"mutex_wait_us":206,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:18:30.905872 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=10.126437
I20260812 06:18:30.943249 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.037s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16671,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.943711 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:30.954514 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.955037 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:31.083266 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.128s	user 0.087s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":9275,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23191,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:31.084048 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=10.126437
I20260812 06:18:31.127307 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.043s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15577,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.127750 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:31.138351 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.139088 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:31.273718 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.134s	user 0.120s	sys 0.014s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":711,"lbm_read_time_us":8470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27086,"lbm_writes_lt_1ms":443,"mutex_wait_us":250,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:31.274435 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=10.126437
I20260812 06:18:31.325896 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20791,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.326491 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:31.337514 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.337984 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:31.384138 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.046s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1330,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2139,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:31.385038 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): free 121006437 bytes of WAL
I20260812 06:18:31.385330 30750 log_reader.cc:385] T 10ed9353f9144d3c9d93c311b2a2f8aa: removed 12 log segments from log reader
I20260812 06:18:31.385399 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000003 (ops 11-15)
I20260812 06:18:31.385442 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000004 (ops 16-20)
I20260812 06:18:31.385470 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000005 (ops 21-24)
I20260812 06:18:31.385501 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000006 (ops 25-29)
I20260812 06:18:31.385524 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000007 (ops 30-34)
I20260812 06:18:31.385555 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000008 (ops 35-39)
I20260812 06:18:31.385591 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000009 (ops 40-44)
I20260812 06:18:31.385623 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000010 (ops 45-49)
I20260812 06:18:31.385650 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000011 (ops 50-54)
I20260812 06:18:31.385677 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000012 (ops 55-59)
I20260812 06:18:31.385704 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000013 (ops 60-64)
I20260812 06:18:31.385733 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000014 (ops 65-69)
I20260812 06:18:31.414577 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:31.415068 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): 447 bytes on disk
I20260812 06:18:31.415781 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.416407 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:31.439641 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:18:31.440223 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:31.450911 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.451363 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:31.653795 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.202s	user 0.143s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918332,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":245,"lbm_read_time_us":13798,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33811,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23936,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:31.655332 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:31.717332 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.062s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21636,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.717866 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:31.729482 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.729972 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:31.900622 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.170s	user 0.113s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":11923,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28072,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:31.901324 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:31.959867 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.058s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19425,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:31.960544 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:31.971443 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.972576 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:32.149183 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.176s	user 0.112s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":115,"lbm_read_time_us":12506,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30254,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:32.149674 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:32.209895 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.060s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18976,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.210451 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:32.222102 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.222625 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:32.413146 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.190s	user 0.125s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":312,"lbm_read_time_us":13032,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32971,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:32.413727 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:32.462988 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.049s	user 0.024s	sys 0.013s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":17459,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.463438 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:32.485078 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.021s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.485833 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:32.661491 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.175s	user 0.127s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":12396,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27728,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:32.662196 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:32.714915 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.053s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23037,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.715426 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:32.725883 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.726315 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:32.888366 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.162s	user 0.121s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":11956,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29238,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:32.889123 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=10.126437
I20260812 06:18:32.930239 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.041s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.930962 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:32.943547 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4363,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.944216 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:32.975142 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1468,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1433,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:32.975764 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): free 120553380 bytes of WAL
I20260812 06:18:32.975991 30750 log_reader.cc:385] T 10ed9353f9144d3c9d93c311b2a2f8aa: removed 12 log segments from log reader
I20260812 06:18:32.976037 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000015 (ops 70-74)
I20260812 06:18:32.976109 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000016 (ops 75-79)
I20260812 06:18:32.976152 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000017 (ops 80-84)
I20260812 06:18:32.976191 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000018 (ops 85-89)
I20260812 06:18:32.976233 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000019 (ops 90-94)
I20260812 06:18:32.976284 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000020 (ops 95-99)
I20260812 06:18:32.976321 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000021 (ops 100-104)
I20260812 06:18:32.976358 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000022 (ops 105-108)
I20260812 06:18:32.976398 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000023 (ops 109-113)
I20260812 06:18:32.976440 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000024 (ops 114-118)
I20260812 06:18:32.976480 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000025 (ops 119-122)
I20260812 06:18:32.976517 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000026 (ops 123-127)
I20260812 06:18:33.003235 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:33.003794 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=6.157687
I20260812 06:18:33.023659 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.020s	user 0.011s	sys 0.005s Metrics: {"bytes_written":7548689,"delete_count":0,"lbm_write_time_us":7561,"lbm_writes_lt_1ms":187,"reinsert_count":0,"update_count":920}
I20260812 06:18:33.024375 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): free 12017949 bytes of WAL
I20260812 06:18:33.024624 30750 log_reader.cc:385] T 10ed9353f9144d3c9d93c311b2a2f8aa: removed 1 log segments from log reader
I20260812 06:18:33.024682 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000027 (ops 128-132)
I20260812 06:18:33.027097 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:33.027444 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:33.244856 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.217s	user 0.149s	sys 0.064s Metrics: {"cfile_cache_miss":617,"cfile_cache_miss_bytes":28261827,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":402,"lbm_read_time_us":16648,"lbm_reads_lt_1ms":653,"lbm_write_time_us":33617,"lbm_writes_lt_1ms":627,"mutex_wait_us":1426,"peak_mem_usage":72805144,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":91,"threads_started":1,"update_count":2920}
I20260812 06:18:33.246539 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): 482 bytes on disk
I20260812 06:18:33.247599 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) 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:18:33.248322 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=15.087375
I20260812 06:18:33.292945 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.044s	user 0.031s	sys 0.013s Metrics: {"bytes_written":17148346,"delete_count":0,"lbm_write_time_us":19529,"lbm_writes_lt_1ms":421,"reinsert_count":0,"update_count":2090}
I20260812 06:18:33.293610 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:33.317973 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.024s	user 0.005s	sys 0.016s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":6122,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:18:33.318449 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:33.326849 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.008s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1723206,"delete_count":0,"lbm_write_time_us":1668,"lbm_writes_lt_1ms":45,"reinsert_count":0,"update_count":210}
I20260812 06:18:33.327284 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.196750
I20260812 06:18:33.334412 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":2577,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:18:33.334846 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:33.558210 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.223s	user 0.143s	sys 0.080s Metrics: {"cfile_cache_miss":650,"cfile_cache_miss_bytes":29574633,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":429,"lbm_read_time_us":16229,"lbm_reads_lt_1ms":690,"lbm_write_time_us":40483,"lbm_writes_lt_1ms":659,"mutex_wait_us":17,"peak_mem_usage":77239416,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":3080}
I20260812 06:18:33.558982 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:33.626974 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.068s	user 0.031s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27574,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.627595 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:33.638463 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.638913 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:33.807508 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.168s	user 0.108s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":661,"lbm_read_time_us":13237,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30155,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:33.808259 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=11.118625
I20260812 06:18:33.844214 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15941,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.844796 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:33.872300 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.027s	user 0.005s	sys 0.020s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6425,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.873016 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:34.041011 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.168s	user 0.099s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":10814,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25724,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:34.041579 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:34.093086 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.051s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19822,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.093603 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:34.109454 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.109967 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:34.264391 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.154s	user 0.114s	sys 0.036s 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":76,"lbm_read_time_us":12363,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30251,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:18:34.265127 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=11.118625
I20260812 06:18:34.303925 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.039s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16859,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:34.304509 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:34.328239 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.023s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4569,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.328881 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:34.339171 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.339861 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:34.502254 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.162s	user 0.113s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":718,"lbm_read_time_us":11058,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30594,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:34.502981 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=14.095187
I20260812 06:18:34.556623 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.053s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22886,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.557164 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:34.568490 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.569190 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:34.603049 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushMRSOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1415,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2148,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:34.603855 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): free 121459775 bytes of WAL
I20260812 06:18:34.604190 30750 log_reader.cc:385] T 10ed9353f9144d3c9d93c311b2a2f8aa: removed 12 log segments from log reader
I20260812 06:18:34.604254 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000028 (ops 133-137)
I20260812 06:18:34.604291 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000029 (ops 138-142)
I20260812 06:18:34.604313 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000030 (ops 143-147)
I20260812 06:18:34.604349 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000031 (ops 148-152)
I20260812 06:18:34.604380 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000032 (ops 153-157)
I20260812 06:18:34.604410 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000033 (ops 158-162)
I20260812 06:18:34.604431 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000034 (ops 163-167)
I20260812 06:18:34.604460 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000035 (ops 168-172)
I20260812 06:18:34.604489 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000036 (ops 173-177)
I20260812 06:18:34.604513 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000037 (ops 178-182)
I20260812 06:18:34.604547 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000038 (ops 183-187)
I20260812 06:18:34.604575 30750 log.cc:1079] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: Deleting log segment in path: /tmp/dist-test-taskNfjB2q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504294286-30277-0/minicluster-data/ts-0-root/wals/10ed9353f9144d3c9d93c311b2a2f8aa/wal-000000039 (ops 188-192)
I20260812 06:18:34.631537 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: LogGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:34.631974 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:34.653343 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.021s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.653863 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa): 493 bytes on disk
I20260812 06:18:34.654302 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: UndoDeltaBlockGCOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.654970 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=2.188937
I20260812 06:18:34.665148 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: FlushDeltaMemStoresOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.666145 30847 maintenance_manager.cc:419] P cd18a697924a423ebc6f03ac1b0f824c: Scheduling MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa): perf score=1.000000
I20260812 06:18:34.753255 30277 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.923s	user 1.789s	sys 0.182s
I20260812 06:18:34.854262 30277 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.101s	user 0.001s	sys 0.000s
I20260812 06:18:34.854823 30277 tablet_server.cc:179] TabletServer@127.29.145.65:0 shutting down...
I20260812 06:18:34.861873 30750 maintenance_manager.cc:643] P cd18a697924a423ebc6f03ac1b0f824c: MajorDeltaCompactionOp(10ed9353f9144d3c9d93c311b2a2f8aa) complete. Timing: real 0.196s	user 0.137s	sys 0.058s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":281,"lbm_read_time_us":14084,"lbm_reads_lt_1ms":770,"lbm_write_time_us":42833,"lbm_writes_lt_1ms":743,"mutex_wait_us":88,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:18:34.862851 30277 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:34.863219 30277 tablet_replica.cc:333] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c: stopping tablet replica
I20260812 06:18:34.863426 30277 raft_consensus.cc:2243] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.863622 30277 raft_consensus.cc:2272] T 10ed9353f9144d3c9d93c311b2a2f8aa P cd18a697924a423ebc6f03ac1b0f824c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.879242 30277 tablet_server.cc:196] TabletServer@127.29.145.65:0 shutdown complete.
I20260812 06:18:34.919894 30277 master.cc:562] Master@127.29.145.126:37463 shutting down...
I20260812 06:18:34.923288 30277 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.923454 30277 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.923503 30277 tablet_replica.cc:333] T 00000000000000000000000000000000 P 79807a89faa14b8181e89b3f4533dfb2: stopping tablet replica
I20260812 06:18:34.935807 30277 master.cc:584] Master@127.29.145.126:37463 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5387 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10721 ms total)

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