[==========] 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:19:12.931305 22894 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.91.190:46081
I20260812 06:19:12.932300 22894 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:19:12.932909 22894 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:12.939393 22899 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:12.939517 22900 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:12.939654 22894 server_base.cc:1061] running on GCE node
W20260812 06:19:12.939797 22902 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:12.940301 22894 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:12.940408 22894 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:12.940454 22894 hybrid_clock.cc:648] HybridClock initialized: now 1786515552940450 us; error 0 us; skew 500 ppm
I20260812 06:19:12.942175 22894 webserver.cc:533] Webserver started at http://127.22.91.190:45203/ using document root <none> and password file <none>
I20260812 06:19:12.942724 22894 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:12.942783 22894 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:12.943039 22894 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:12.944739 22894 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/master-0-root/instance:
uuid: "d7aaef5a19284cb88ac6cdec1d978398"
format_stamp: "Formatted at 2026-08-12 06:19:12 on dist-test-slave-c12x"
I20260812 06:19:12.948319 22894 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:12.950429 22911 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:12.951464 22894 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:12.951609 22894 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/master-0-root
uuid: "d7aaef5a19284cb88ac6cdec1d978398"
format_stamp: "Formatted at 2026-08-12 06:19:12 on dist-test-slave-c12x"
I20260812 06:19:12.951730 22894 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:12.990918 22894 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:12.991688 22894 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:12.991888 22894 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.000150 22989 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.190:46081 every 8 connection(s)
I20260812 06:19:13.000159 22894 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.190:46081
I20260812 06:19:13.002475 22991 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.007864 22991 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: Bootstrap starting.
I20260812 06:19:13.010250 22991 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.011178 22991 log.cc:826] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:13.012959 22991 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: No bootstrap required, opened a new log
I20260812 06:19:13.015899 22991 raft_consensus.cc:359] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d7aaef5a19284cb88ac6cdec1d978398" member_type: VOTER }
I20260812 06:19:13.016098 22991 raft_consensus.cc:385] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.016172 22991 raft_consensus.cc:740] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d7aaef5a19284cb88ac6cdec1d978398, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.016811 22991 consensus_queue.cc:260] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [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: "d7aaef5a19284cb88ac6cdec1d978398" member_type: VOTER }
I20260812 06:19:13.016995 22991 raft_consensus.cc:399] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.017077 22991 raft_consensus.cc:493] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.017249 22991 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.018110 22991 raft_consensus.cc:515] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d7aaef5a19284cb88ac6cdec1d978398" member_type: VOTER }
I20260812 06:19:13.018559 22991 leader_election.cc:304] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [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: d7aaef5a19284cb88ac6cdec1d978398; no voters: 
I20260812 06:19:13.018898 22991 leader_election.cc:290] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.019112 22998 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.019388 22998 raft_consensus.cc:697] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 1 LEADER]: Becoming Leader. State: Replica: d7aaef5a19284cb88ac6cdec1d978398, State: Running, Role: LEADER
I20260812 06:19:13.019863 22998 consensus_queue.cc:237] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [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: "d7aaef5a19284cb88ac6cdec1d978398" member_type: VOTER }
I20260812 06:19:13.020007 22991 sys_catalog.cc:565] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:13.021937 23001 sys_catalog.cc:455] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d7aaef5a19284cb88ac6cdec1d978398" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d7aaef5a19284cb88ac6cdec1d978398" member_type: VOTER } }
I20260812 06:19:13.022068 23001 sys_catalog.cc:458] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.022329 23002 sys_catalog.cc:455] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d7aaef5a19284cb88ac6cdec1d978398. Latest consensus state: current_term: 1 leader_uuid: "d7aaef5a19284cb88ac6cdec1d978398" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d7aaef5a19284cb88ac6cdec1d978398" member_type: VOTER } }
I20260812 06:19:13.022409 23002 sys_catalog.cc:458] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.022493 22894 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:13.024574 23026 catalog_manager.cc:1594] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:13.024642 23026 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:13.024725 23024 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:13.025529 23024 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:13.030313 23024 catalog_manager.cc:1383] Generated new cluster ID: 9e8e5666b3f34491bdd5e1fe2bfbfe7c
I20260812 06:19:13.030383 23024 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:13.047940 23024 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:13.049132 23024 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:13.059449 23024 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: Generated new TSK 0
I20260812 06:19:13.060129 23024 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:13.087376 22894 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:13.090175 23034 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.090190 23041 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.090399 23035 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:13.090871 22894 server_base.cc:1061] running on GCE node
I20260812 06:19:13.091073 22894 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.091114 22894 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:13.091130 22894 hybrid_clock.cc:648] HybridClock initialized: now 1786515553091130 us; error 0 us; skew 500 ppm
I20260812 06:19:13.092141 22894 webserver.cc:533] Webserver started at http://127.22.91.129:46437/ using document root <none> and password file <none>
I20260812 06:19:13.092319 22894 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.092378 22894 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.092475 22894 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.092928 22894 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/instance:
uuid: "1a8884d851fa448495bf8200af55fdf8"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-c12x"
I20260812 06:19:13.094544 22894 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:13.095582 23055 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.095844 22894 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:13.095916 22894 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root
uuid: "1a8884d851fa448495bf8200af55fdf8"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-c12x"
I20260812 06:19:13.096014 22894 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:13.101871 22894 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.102319 22894 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.102795 22894 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:13.103657 22894 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:13.103708 22894 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.103773 22894 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:13.103811 22894 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.110598 22894 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.129:43049
I20260812 06:19:13.110628 23154 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.129:43049 every 8 connection(s)
I20260812 06:19:13.125149 23155 heartbeater.cc:344] Connected to a master server at 127.22.91.190:46081
I20260812 06:19:13.125545 23155 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:13.126019 23155 heartbeater.cc:507] Master 127.22.91.190:46081 requested a full tablet report, sending...
I20260812 06:19:13.127362 22938 ts_manager.cc:194] Registered new tserver with Master: 1a8884d851fa448495bf8200af55fdf8 (127.22.91.129:43049)
I20260812 06:19:13.127959 22894 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016721896s
I20260812 06:19:13.128625 22938 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50826
I20260812 06:19:13.138200 22938 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50834:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:13.152184 23094 tablet_service.cc:1511] Processing CreateTablet for tablet 0212417f8de2450d99c3119682cb7566 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1cc66b3c3101461192c98c9aabce0041]), partition=
I20260812 06:19:13.152617 23094 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0212417f8de2450d99c3119682cb7566. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.155306 23175 tablet_bootstrap.cc:492] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Bootstrap starting.
I20260812 06:19:13.156320 23175 tablet_bootstrap.cc:654] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.157639 23175 tablet_bootstrap.cc:492] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: No bootstrap required, opened a new log
I20260812 06:19:13.157754 23175 ts_tablet_manager.cc:1403] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:13.158192 23175 raft_consensus.cc:359] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a8884d851fa448495bf8200af55fdf8" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 43049 } }
I20260812 06:19:13.158310 23175 raft_consensus.cc:385] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.158365 23175 raft_consensus.cc:740] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1a8884d851fa448495bf8200af55fdf8, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.158628 23175 consensus_queue.cc:260] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [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: "1a8884d851fa448495bf8200af55fdf8" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 43049 } }
I20260812 06:19:13.158756 23175 raft_consensus.cc:399] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.158815 23175 raft_consensus.cc:493] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.158878 23175 raft_consensus.cc:3060] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.159694 23175 raft_consensus.cc:515] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a8884d851fa448495bf8200af55fdf8" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 43049 } }
I20260812 06:19:13.159850 23175 leader_election.cc:304] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [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: 1a8884d851fa448495bf8200af55fdf8; no voters: 
I20260812 06:19:13.160090 23175 leader_election.cc:290] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.160183 23177 raft_consensus.cc:2804] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.160359 23177 raft_consensus.cc:697] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 1 LEADER]: Becoming Leader. State: Replica: 1a8884d851fa448495bf8200af55fdf8, State: Running, Role: LEADER
I20260812 06:19:13.160494 23177 consensus_queue.cc:237] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [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: "1a8884d851fa448495bf8200af55fdf8" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 43049 } }
I20260812 06:19:13.160789 23155 heartbeater.cc:499] Master 127.22.91.190:46081 was elected leader, sending a full tablet report...
I20260812 06:19:13.161149 23175 ts_tablet_manager.cc:1434] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:13.163292 22938 catalog_manager.cc:5719] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1a8884d851fa448495bf8200af55fdf8 (127.22.91.129). New cstate: current_term: 1 leader_uuid: "1a8884d851fa448495bf8200af55fdf8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a8884d851fa448495bf8200af55fdf8" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 43049 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:13.230299 22894 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.014s	sys 0.013s
I20260812 06:19:13.361617 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushMRSOp(0212417f8de2450d99c3119682cb7566): perf score=19.054940
I20260812 06:19:13.520337 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushMRSOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.158s	user 0.110s	sys 0.048s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":200,"delete_count":0,"dirs.queue_time_us":2425,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":879,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40911,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":151296,"thread_start_us":121,"threads_started":1,"update_count":1050}
I20260812 06:19:13.521612 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling LogGCOp(0212417f8de2450d99c3119682cb7566): free 20743880 bytes of WAL
I20260812 06:19:13.521986 23062 log_reader.cc:385] T 0212417f8de2450d99c3119682cb7566: removed 2 log segments from log reader
I20260812 06:19:13.522058 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000001 (ops 1-6)
I20260812 06:19:13.522113 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000002 (ops 7-11)
I20260812 06:19:13.527397 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: LogGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:13.527838 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:13.540401 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.012s	user 0.010s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.540891 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566): 16411394 bytes on disk
I20260812 06:19:13.541467 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:13.541882 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:13.662406 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.120s	user 0.076s	sys 0.040s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":617,"lbm_read_time_us":7062,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21734,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":318,"threads_started":5,"update_count":1500}
I20260812 06:19:13.663072 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:13.710207 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.047s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17256,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:13.710714 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:13.721506 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.722275 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:13.851532 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.129s	user 0.121s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":10386,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22569,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:13.852118 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:13.899572 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.047s	user 0.016s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17674,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:13.900211 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:13.917073 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.017s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.917702 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.064960 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.147s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":660,"lbm_read_time_us":10577,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23330,"lbm_writes_lt_1ms":443,"mutex_wait_us":269,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:19:14.065528 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:14.112963 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.047s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16330,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.113483 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:14.124727 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.125425 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.244441 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.119s	user 0.081s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":872,"lbm_read_time_us":8351,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21636,"lbm_writes_lt_1ms":443,"mutex_wait_us":343,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:14.245095 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:14.290977 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.046s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20556,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.291599 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:14.303207 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4421,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.303825 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.432159 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.128s	user 0.102s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1282,"lbm_read_time_us":9915,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24217,"lbm_writes_lt_1ms":443,"mutex_wait_us":424,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:19:14.432783 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:14.484330 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.051s	user 0.019s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19027,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.484890 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:14.495296 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.495879 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.647996 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.152s	user 0.114s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":595,"lbm_read_time_us":9874,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24898,"lbm_writes_lt_1ms":443,"mutex_wait_us":258,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:14.648711 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:14.694990 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.046s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17176,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.695573 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:14.706337 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.706974 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.834005 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":102,"lbm_read_time_us":8327,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25363,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:14.834753 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:14.876215 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.041s	user 0.013s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17199,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.877099 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:14.892685 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.015s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.893244 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushMRSOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.919386 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushMRSOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.026s	user 0.021s	sys 0.003s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":281,"dirs.run_wall_time_us":1627,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:14.920226 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling LogGCOp(0212417f8de2450d99c3119682cb7566): free 124257246 bytes of WAL
I20260812 06:19:14.920447 23062 log_reader.cc:385] T 0212417f8de2450d99c3119682cb7566: removed 12 log segments from log reader
I20260812 06:19:14.920511 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000003 (ops 12-16)
I20260812 06:19:14.920599 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000004 (ops 17-21)
I20260812 06:19:14.920653 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000005 (ops 22-26)
I20260812 06:19:14.920696 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000006 (ops 27-31)
I20260812 06:19:14.920735 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000007 (ops 32-36)
I20260812 06:19:14.920773 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000008 (ops 37-40)
I20260812 06:19:14.920810 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000009 (ops 41-45)
I20260812 06:19:14.920848 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000010 (ops 46-50)
I20260812 06:19:14.920885 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000011 (ops 51-55)
I20260812 06:19:14.920922 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000012 (ops 56-60)
I20260812 06:19:14.920959 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000013 (ops 61-65)
I20260812 06:19:14.920996 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000014 (ops 66-70)
I20260812 06:19:14.946914 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: LogGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {"spinlock_wait_cycles":1792}
I20260812 06:19:14.947453 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=5.165500
I20260812 06:19:14.962845 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":6441039,"delete_count":0,"lbm_write_time_us":6285,"lbm_writes_lt_1ms":160,"reinsert_count":0,"update_count":785}
I20260812 06:19:14.963341 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566): 481 bytes on disk
I20260812 06:19:14.963963 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.964520 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:14.973258 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":1764227,"delete_count":0,"lbm_write_time_us":2550,"lbm_writes_lt_1ms":46,"reinsert_count":0,"update_count":215}
I20260812 06:19:14.973721 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:15.133711 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.160s	user 0.123s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877283,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2578,"lbm_read_time_us":12213,"lbm_reads_lt_1ms":666,"lbm_write_time_us":29615,"lbm_writes_lt_1ms":643,"mutex_wait_us":2156,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:19:15.134204 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:15.192507 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.058s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25208,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.192979 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:15.204952 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.205421 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:15.369530 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.164s	user 0.121s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":638,"lbm_read_time_us":10195,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30247,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:19:15.370240 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:15.423002 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.053s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20266,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.423676 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:15.578943 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.155s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":223,"lbm_read_time_us":9676,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24319,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":2000}
I20260812 06:19:15.579775 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:15.643656 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.064s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20446,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.644330 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:15.670480 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.026s	user 0.010s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.671007 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:15.867086 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.196s	user 0.137s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":137,"lbm_read_time_us":12865,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30910,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:15.867785 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:15.917160 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.049s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20526,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.917692 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:15.928398 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.929260 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:16.076360 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.147s	user 0.106s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":11784,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27471,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:16.077116 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=11.118625
I20260812 06:19:16.114414 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.037s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15879,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:16.115103 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:16.137315 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.022s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.137866 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:16.151193 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5104,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.151721 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:16.293898 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.142s	user 0.105s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":298,"lbm_read_time_us":11628,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29162,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:19:16.296109 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:16.331938 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15373,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.332516 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:16.347189 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.347839 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushMRSOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:16.381155 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushMRSOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.033s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1272,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1609,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:16.381860 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling LogGCOp(0212417f8de2450d99c3119682cb7566): free 121459505 bytes of WAL
I20260812 06:19:16.382087 23062 log_reader.cc:385] T 0212417f8de2450d99c3119682cb7566: removed 12 log segments from log reader
I20260812 06:19:16.382131 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000015 (ops 71-75)
I20260812 06:19:16.382177 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000016 (ops 76-80)
I20260812 06:19:16.382225 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000017 (ops 81-85)
I20260812 06:19:16.382266 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000018 (ops 86-90)
I20260812 06:19:16.382313 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000019 (ops 91-95)
I20260812 06:19:16.382351 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000020 (ops 96-100)
I20260812 06:19:16.382391 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000021 (ops 101-105)
I20260812 06:19:16.382431 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000022 (ops 106-110)
I20260812 06:19:16.382476 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000023 (ops 111-115)
I20260812 06:19:16.382515 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000024 (ops 116-120)
I20260812 06:19:16.382561 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000025 (ops 121-125)
I20260812 06:19:16.382603 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000026 (ops 126-130)
I20260812 06:19:16.410115 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: LogGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:16.410650 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=3.181125
I20260812 06:19:16.427721 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6805,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:16.428200 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566): 472 bytes on disk
I20260812 06:19:16.428615 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.429148 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:16.440061 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.440744 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:16.619910 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.179s	user 0.154s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":659,"lbm_read_time_us":11798,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36140,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:16.620748 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:16.670539 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.050s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19620,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.671082 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:16.687225 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6024,"lbm_writes_lt_1ms":103,"mutex_wait_us":2,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.687937 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:16.881003 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.193s	user 0.141s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":13332,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26778,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:19:16.881669 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:16.936805 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.055s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.937279 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:16.948437 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.949141 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:17.104336 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.155s	user 0.139s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":12266,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31172,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26624,"update_count":2500}
I20260812 06:19:17.104956 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:17.143203 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.038s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16354,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.143828 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:17.155843 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.156337 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:17.290325 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.134s	user 0.117s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1627,"lbm_read_time_us":9368,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26025,"lbm_writes_lt_1ms":443,"mutex_wait_us":552,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:17.291085 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:17.333555 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.042s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17441,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.334087 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:17.345204 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.345984 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:17.466543 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.120s	user 0.084s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1103,"lbm_read_time_us":7744,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22998,"lbm_writes_lt_1ms":443,"mutex_wait_us":381,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:17.467229 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:17.521763 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.054s	user 0.026s	sys 0.025s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20010,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:19:17.522300 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:17.533180 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.533624 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:17.693675 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.160s	user 0.074s	sys 0.082s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":10723,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27388,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:19:17.694413 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=10.126437
I20260812 06:19:17.741454 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.047s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16842,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.741997 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:17.754297 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.755086 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushMRSOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:17.787220 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushMRSOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1179,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1328,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:17.787883 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling LogGCOp(0212417f8de2450d99c3119682cb7566): free 123804447 bytes of WAL
I20260812 06:19:17.788103 23062 log_reader.cc:385] T 0212417f8de2450d99c3119682cb7566: removed 12 log segments from log reader
I20260812 06:19:17.788146 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000027 (ops 131-135)
I20260812 06:19:17.788193 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000028 (ops 136-140)
I20260812 06:19:17.788239 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000029 (ops 141-145)
I20260812 06:19:17.788281 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000030 (ops 146-150)
I20260812 06:19:17.788324 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000031 (ops 151-155)
I20260812 06:19:17.788364 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000032 (ops 156-160)
I20260812 06:19:17.788403 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000033 (ops 161-164)
I20260812 06:19:17.788443 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000034 (ops 165-169)
I20260812 06:19:17.788482 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000035 (ops 170-174)
I20260812 06:19:17.788522 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000036 (ops 175-179)
I20260812 06:19:17.788568 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000037 (ops 180-184)
I20260812 06:19:17.788609 23062 log.cc:1079] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/0212417f8de2450d99c3119682cb7566/wal-000000038 (ops 185-188)
I20260812 06:19:17.815375 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: LogGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:17.815834 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566): 448 bytes on disk
I20260812 06:19:17.816342 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: UndoDeltaBlockGCOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:17.816875 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=5.165500
I20260812 06:19:17.845952 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.029s	user 0.015s	sys 0.011s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":7982,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:19:17.846683 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:17.853652 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":2148,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:19:17.854143 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:18.051175 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.197s	user 0.113s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877286,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":597,"lbm_read_time_us":15158,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32132,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:18.051997 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=14.095187
I20260812 06:19:18.104871 22894 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.874s	user 1.786s	sys 0.119s
I20260812 06:19:18.120494 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.068s	user 0.040s	sys 0.023s 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:19:18.121120 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566): perf score=2.188937
I20260812 06:19:18.135653 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: FlushDeltaMemStoresOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.014s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":500}
I20260812 06:19:18.136294 23156 maintenance_manager.cc:419] P 1a8884d851fa448495bf8200af55fdf8: Scheduling MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566): perf score=1.000000
I20260812 06:19:18.199697 22894 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.004s	sys 0.000s
I20260812 06:19:18.200338 22894 tablet_server.cc:179] TabletServer@127.22.91.129:0 shutting down...
I20260812 06:19:18.278136 23062 maintenance_manager.cc:643] P 1a8884d851fa448495bf8200af55fdf8: MajorDeltaCompactionOp(0212417f8de2450d99c3119682cb7566) complete. Timing: real 0.142s	user 0.095s	sys 0.046s Metrics: {"cfile_cache_hit":193,"cfile_cache_hit_bytes":7879479,"cfile_cache_miss":339,"cfile_cache_miss_bytes":16895209,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":8085,"lbm_reads_lt_1ms":371,"lbm_write_time_us":26857,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":162048,"update_count":2500}
I20260812 06:19:18.278923 22894 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:18.279345 22894 tablet_replica.cc:333] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8: stopping tablet replica
I20260812 06:19:18.279636 22894 raft_consensus.cc:2243] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:18.279892 22894 raft_consensus.cc:2272] T 0212417f8de2450d99c3119682cb7566 P 1a8884d851fa448495bf8200af55fdf8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:18.285866 22894 tablet_server.cc:196] TabletServer@127.22.91.129:0 shutdown complete.
I20260812 06:19:18.325049 22894 master.cc:562] Master@127.22.91.190:46081 shutting down...
I20260812 06:19:18.328711 22894 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:18.328913 22894 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:18.329015 22894 tablet_replica.cc:333] T 00000000000000000000000000000000 P d7aaef5a19284cb88ac6cdec1d978398: stopping tablet replica
I20260812 06:19:18.342103 22894 master.cc:584] Master@127.22.91.190:46081 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5498 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:18.429399 22894 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.91.190:36147
I20260812 06:19:18.429797 22894 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:18.432523 22894 server_base.cc:1061] running on GCE node
W20260812 06:19:18.432657 23201 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:18.432670 23202 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:18.432693 23205 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.432966 22894 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:18.433027 22894 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:18.433051 22894 hybrid_clock.cc:648] HybridClock initialized: now 1786515558433051 us; error 0 us; skew 500 ppm
I20260812 06:19:18.433871 22894 webserver.cc:533] Webserver started at http://127.22.91.190:46059/ using document root <none> and password file <none>
I20260812 06:19:18.434043 22894 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:18.434109 22894 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:18.434188 22894 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:18.434587 22894 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/master-0-root/instance:
uuid: "c064f35075394a5c9e8549f22847c558"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-c12x"
I20260812 06:19:18.436172 22894 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:18.437083 23211 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.437330 22894 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:18.437414 22894 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/master-0-root
uuid: "c064f35075394a5c9e8549f22847c558"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-c12x"
I20260812 06:19:18.437501 22894 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:18.451797 22894 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:18.452215 22894 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:18.456544 22894 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.190:36147
I20260812 06:19:18.458992 23297 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.190:36147 every 8 connection(s)
I20260812 06:19:18.459331 23299 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:18.470577 23299 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558: Bootstrap starting.
I20260812 06:19:18.471642 23299 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:18.472865 23299 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558: No bootstrap required, opened a new log
I20260812 06:19:18.473305 23299 raft_consensus.cc:359] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c064f35075394a5c9e8549f22847c558" member_type: VOTER }
I20260812 06:19:18.473418 23299 raft_consensus.cc:385] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:18.473465 23299 raft_consensus.cc:740] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c064f35075394a5c9e8549f22847c558, State: Initialized, Role: FOLLOWER
I20260812 06:19:18.473660 23299 consensus_queue.cc:260] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [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: "c064f35075394a5c9e8549f22847c558" member_type: VOTER }
I20260812 06:19:18.473773 23299 raft_consensus.cc:399] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:18.473820 23299 raft_consensus.cc:493] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:18.473877 23299 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:18.474629 23299 raft_consensus.cc:515] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c064f35075394a5c9e8549f22847c558" member_type: VOTER }
I20260812 06:19:18.474773 23299 leader_election.cc:304] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [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: c064f35075394a5c9e8549f22847c558; no voters: 
I20260812 06:19:18.474982 23299 leader_election.cc:290] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:18.475149 23305 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:18.475485 23299 sys_catalog.cc:565] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:18.475521 23305 raft_consensus.cc:697] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 1 LEADER]: Becoming Leader. State: Replica: c064f35075394a5c9e8549f22847c558, State: Running, Role: LEADER
I20260812 06:19:18.475708 23305 consensus_queue.cc:237] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [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: "c064f35075394a5c9e8549f22847c558" member_type: VOTER }
I20260812 06:19:18.476188 23308 sys_catalog.cc:455] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c064f35075394a5c9e8549f22847c558. Latest consensus state: current_term: 1 leader_uuid: "c064f35075394a5c9e8549f22847c558" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c064f35075394a5c9e8549f22847c558" member_type: VOTER } }
I20260812 06:19:18.476297 23308 sys_catalog.cc:458] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:18.476483 23306 sys_catalog.cc:455] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c064f35075394a5c9e8549f22847c558" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c064f35075394a5c9e8549f22847c558" member_type: VOTER } }
I20260812 06:19:18.476558 23306 sys_catalog.cc:458] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:18.477064 23319 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:18.477785 23319 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:18.478037 22894 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:18.479920 23319 catalog_manager.cc:1383] Generated new cluster ID: 5e13a1cf634a4dd88a93bcc01e356348
I20260812 06:19:18.479987 23319 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:18.497236 23319 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:18.497819 23319 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:18.504676 23319 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558: Generated new TSK 0
I20260812 06:19:18.504856 23319 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:18.510442 22894 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:18.512460 23343 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.512590 22894 server_base.cc:1061] running on GCE node
W20260812 06:19:18.512595 23340 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:18.512677 23338 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:19:18.512909 22894 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:18.512956 22894 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:18.512971 22894 hybrid_clock.cc:648] HybridClock initialized: now 1786515558512972 us; error 0 us; skew 500 ppm
I20260812 06:19:18.513876 22894 webserver.cc:533] Webserver started at http://127.22.91.129:34505/ using document root <none> and password file <none>
I20260812 06:19:18.514075 22894 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:18.514139 22894 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:18.514222 22894 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:18.514618 22894 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/instance:
uuid: "e3e781739cd64e4f8b0b050732b6cd4c"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-c12x"
I20260812 06:19:18.516255 22894 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:18.517256 23354 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.517486 22894 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:18.517570 22894 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root
uuid: "e3e781739cd64e4f8b0b050732b6cd4c"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-c12x"
I20260812 06:19:18.517652 22894 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:18.540434 22894 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:18.540891 22894 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:18.541257 22894 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:18.541760 22894 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:18.541821 22894 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.541874 22894 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:18.541920 22894 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.546525 22894 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.129:37827
I20260812 06:19:18.546562 23442 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.129:37827 every 8 connection(s)
I20260812 06:19:18.556991 23445 heartbeater.cc:344] Connected to a master server at 127.22.91.190:36147
I20260812 06:19:18.557137 23445 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:18.557392 23445 heartbeater.cc:507] Master 127.22.91.190:36147 requested a full tablet report, sending...
I20260812 06:19:18.558090 23241 ts_manager.cc:194] Registered new tserver with Master: e3e781739cd64e4f8b0b050732b6cd4c (127.22.91.129:37827)
I20260812 06:19:18.559129 23241 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37018
I20260812 06:19:18.559154 22894 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012212201s
I20260812 06:19:18.566252 23241 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37020:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:18.575125 23397 tablet_service.cc:1511] Processing CreateTablet for tablet a4656e26278548e7bc763541a5f10e2a (DEFAULT_TABLE table=heavy-update-compaction-test [id=4bd79175c8f84e9fb14a5852790dcfea]), partition=
I20260812 06:19:18.575415 23397 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a4656e26278548e7bc763541a5f10e2a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:18.577740 23463 tablet_bootstrap.cc:492] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Bootstrap starting.
I20260812 06:19:18.578467 23463 tablet_bootstrap.cc:654] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:18.579572 23463 tablet_bootstrap.cc:492] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: No bootstrap required, opened a new log
I20260812 06:19:18.579665 23463 ts_tablet_manager.cc:1403] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:18.580075 23463 raft_consensus.cc:359] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e781739cd64e4f8b0b050732b6cd4c" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 37827 } }
I20260812 06:19:18.580183 23463 raft_consensus.cc:385] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:18.580207 23463 raft_consensus.cc:740] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e3e781739cd64e4f8b0b050732b6cd4c, State: Initialized, Role: FOLLOWER
I20260812 06:19:18.580366 23463 consensus_queue.cc:260] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [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: "e3e781739cd64e4f8b0b050732b6cd4c" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 37827 } }
I20260812 06:19:18.580468 23463 raft_consensus.cc:399] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:18.580519 23463 raft_consensus.cc:493] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:18.580580 23463 raft_consensus.cc:3060] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:18.581316 23463 raft_consensus.cc:515] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e781739cd64e4f8b0b050732b6cd4c" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 37827 } }
I20260812 06:19:18.581459 23463 leader_election.cc:304] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [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: e3e781739cd64e4f8b0b050732b6cd4c; no voters: 
I20260812 06:19:18.581672 23463 leader_election.cc:290] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:18.581785 23465 raft_consensus.cc:2804] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:18.582016 23463 ts_tablet_manager.cc:1434] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:18.582047 23445 heartbeater.cc:499] Master 127.22.91.190:36147 was elected leader, sending a full tablet report...
I20260812 06:19:18.582087 23465 raft_consensus.cc:697] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 1 LEADER]: Becoming Leader. State: Replica: e3e781739cd64e4f8b0b050732b6cd4c, State: Running, Role: LEADER
I20260812 06:19:18.582207 23465 consensus_queue.cc:237] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [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: "e3e781739cd64e4f8b0b050732b6cd4c" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 37827 } }
I20260812 06:19:18.583565 23241 catalog_manager.cc:5719] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c reported cstate change: term changed from 0 to 1, leader changed from <none> to e3e781739cd64e4f8b0b050732b6cd4c (127.22.91.129). New cstate: current_term: 1 leader_uuid: "e3e781739cd64e4f8b0b050732b6cd4c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e781739cd64e4f8b0b050732b6cd4c" member_type: VOTER last_known_addr { host: "127.22.91.129" port: 37827 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:18.643296 22894 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.019s	sys 0.004s
I20260812 06:19:18.797456 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushMRSOp(a4656e26278548e7bc763541a5f10e2a): perf score=19.054940
I20260812 06:19:18.959643 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushMRSOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.162s	user 0.115s	sys 0.045s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":733,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41162,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:19:18.960301 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling LogGCOp(a4656e26278548e7bc763541a5f10e2a): free 20290830 bytes of WAL
I20260812 06:19:18.960644 23361 log_reader.cc:385] T a4656e26278548e7bc763541a5f10e2a: removed 2 log segments from log reader
I20260812 06:19:18.960700 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000001 (ops 1-6)
I20260812 06:19:18.960752 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000002 (ops 7-10)
I20260812 06:19:18.965240 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: LogGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:18.965672 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:18.983533 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.984078 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a): 16411395 bytes on disk
I20260812 06:19:18.984679 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.985147 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:19.139209 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.154s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":562,"lbm_read_time_us":10431,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23331,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":321,"threads_started":5,"update_count":2000}
I20260812 06:19:19.139848 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:19.183858 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.044s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19523,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:19.184437 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:19.196928 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.197535 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:19.352001 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.154s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":9276,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29991,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:19:19.352691 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:19.411954 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.059s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23995,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.412494 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:19.423784 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4185,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.424465 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:19.582794 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.158s	user 0.126s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":413,"lbm_read_time_us":10520,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29678,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:19.583344 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=12.110812
I20260812 06:19:19.627329 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.044s	user 0.030s	sys 0.009s Metrics: {"bytes_written":13907426,"delete_count":0,"lbm_write_time_us":19022,"lbm_writes_lt_1ms":342,"reinsert_count":0,"update_count":1695}
I20260812 06:19:19.627982 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.196750
I20260812 06:19:19.638214 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2502679,"delete_count":0,"lbm_write_time_us":3057,"lbm_writes_lt_1ms":64,"reinsert_count":0,"update_count":305}
I20260812 06:19:19.638868 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:19.800171 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.161s	user 0.107s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672233,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":9909,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23677,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:19:19.800743 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:19.852736 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.052s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":23361,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.853317 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:19.882091 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.029s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.882731 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:20.077769 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.195s	user 0.139s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":842,"lbm_read_time_us":13976,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29204,"lbm_writes_lt_1ms":543,"mutex_wait_us":141,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:20.078400 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:20.133751 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.055s	user 0.049s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24732,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.134379 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:20.147850 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.148357 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushMRSOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:20.180850 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushMRSOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1333,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2116,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:20.181507 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling LogGCOp(a4656e26278548e7bc763541a5f10e2a): free 112692316 bytes of WAL
I20260812 06:19:20.181825 23361 log_reader.cc:385] T a4656e26278548e7bc763541a5f10e2a: removed 11 log segments from log reader
I20260812 06:19:20.181891 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000003 (ops 11-15)
I20260812 06:19:20.181939 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000004 (ops 16-20)
I20260812 06:19:20.181968 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000005 (ops 21-25)
I20260812 06:19:20.181994 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000006 (ops 26-30)
I20260812 06:19:20.182032 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000007 (ops 31-35)
I20260812 06:19:20.182067 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000008 (ops 36-40)
I20260812 06:19:20.182106 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000009 (ops 41-45)
I20260812 06:19:20.182142 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000010 (ops 46-50)
I20260812 06:19:20.182180 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000011 (ops 51-55)
I20260812 06:19:20.182216 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000012 (ops 56-60)
I20260812 06:19:20.182256 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000013 (ops 61-65)
I20260812 06:19:20.212778 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: LogGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:20.213222 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a): 447 bytes on disk
I20260812 06:19:20.213699 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:19:20.214351 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=3.181125
I20260812 06:19:20.235390 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.021s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4695,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:20.235900 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:20.246340 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:20.246817 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:20.490459 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.243s	user 0.139s	sys 0.104s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":791,"lbm_read_time_us":17063,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43540,"lbm_writes_lt_1ms":743,"mutex_wait_us":302,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:19:20.491185 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=18.063937
I20260812 06:19:20.551050 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.060s	user 0.018s	sys 0.031s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24411,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:20.551540 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:20.563681 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4389,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.564172 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:20.770750 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.206s	user 0.129s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1490,"lbm_read_time_us":13780,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34172,"lbm_writes_lt_1ms":643,"mutex_wait_us":596,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:20.771359 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=17.071750
I20260812 06:19:20.840973 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.069s	user 0.035s	sys 0.022s Metrics: {"bytes_written":18912369,"delete_count":0,"lbm_write_time_us":26486,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":463,"reinsert_count":0,"update_count":2305}
I20260812 06:19:20.841439 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=4.173312
I20260812 06:19:20.859107 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":5702610,"delete_count":0,"lbm_write_time_us":7207,"lbm_writes_lt_1ms":142,"reinsert_count":0,"update_count":695}
I20260812 06:19:20.859640 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:21.069792 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.209s	user 0.113s	sys 0.093s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":601,"lbm_read_time_us":15109,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35030,"lbm_writes_lt_1ms":643,"mutex_wait_us":246,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:19:21.071624 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=16.079562
I20260812 06:19:21.133564 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.062s	user 0.023s	sys 0.029s Metrics: {"bytes_written":17640626,"delete_count":0,"lbm_write_time_us":24779,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2150}
I20260812 06:19:21.134069 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=5.165500
I20260812 06:19:21.153476 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6974357,"delete_count":0,"lbm_write_time_us":8164,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:19:21.153923 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:21.364892 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.211s	user 0.113s	sys 0.096s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1085,"lbm_read_time_us":14151,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33653,"lbm_writes_lt_1ms":643,"mutex_wait_us":346,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":61568,"update_count":3000}
I20260812 06:19:21.365736 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=15.087375
I20260812 06:19:21.425815 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.060s	user 0.033s	sys 0.020s Metrics: {"bytes_written":17435507,"delete_count":0,"lbm_write_time_us":24434,"lbm_writes_lt_1ms":428,"reinsert_count":0,"update_count":2125}
I20260812 06:19:21.426409 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:21.441915 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3487284,"delete_count":0,"lbm_write_time_us":5597,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:19:21.442459 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:21.453023 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3881,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.453665 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:21.668104 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.214s	user 0.131s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877196,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":244,"lbm_read_time_us":13443,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37125,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":3000}
I20260812 06:19:21.668897 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:21.715054 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.046s	user 0.018s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20641,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.715777 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:21.726945 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4432,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.727509 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushMRSOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:21.762773 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushMRSOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":395,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2103,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:21.763608 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling LogGCOp(a4656e26278548e7bc763541a5f10e2a): free 132571389 bytes of WAL
I20260812 06:19:21.763870 23361 log_reader.cc:385] T a4656e26278548e7bc763541a5f10e2a: removed 13 log segments from log reader
I20260812 06:19:21.763940 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000014 (ops 66-70)
I20260812 06:19:21.763990 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000015 (ops 71-74)
I20260812 06:19:21.764070 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000016 (ops 75-79)
I20260812 06:19:21.764112 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000017 (ops 80-84)
I20260812 06:19:21.764149 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000018 (ops 85-89)
I20260812 06:19:21.764186 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000019 (ops 90-94)
I20260812 06:19:21.764227 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000020 (ops 95-99)
I20260812 06:19:21.764268 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000021 (ops 100-104)
I20260812 06:19:21.764309 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000022 (ops 105-108)
I20260812 06:19:21.764349 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000023 (ops 109-113)
I20260812 06:19:21.764389 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000024 (ops 114-118)
I20260812 06:19:21.764430 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000025 (ops 119-123)
I20260812 06:19:21.764469 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000026 (ops 124-128)
I20260812 06:19:21.793088 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: LogGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:21.794226 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a): 483 bytes on disk
I20260812 06:19:21.794642 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:21.795234 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=3.181125
I20260812 06:19:21.809525 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:21.809964 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:21.819653 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.010s	user 0.007s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3613,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.820101 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:22.042507 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.222s	user 0.125s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":846,"lbm_read_time_us":15720,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39165,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11264,"thread_start_us":103,"threads_started":1,"update_count":3500}
I20260812 06:19:22.043259 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=18.063937
I20260812 06:19:22.107190 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.064s	user 0.052s	sys 0.008s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":29367,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:22.107729 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:22.118928 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4040,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.119485 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:22.283277 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.164s	user 0.122s	sys 0.041s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":12113,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33423,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":3000}
I20260812 06:19:22.284027 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:22.341922 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.058s	user 0.044s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26207,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.342479 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:22.354228 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.354710 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:22.514571 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.160s	user 0.124s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":10058,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28801,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:19:22.515336 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:22.570413 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.055s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22215,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.570947 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:22.729701 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.159s	user 0.113s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":170,"lbm_read_time_us":10713,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24789,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:19:22.730407 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:22.781468 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.051s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.781971 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:22.792752 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.793506 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:22.985057 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.191s	user 0.121s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":12262,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31691,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:19:22.985800 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=14.095187
I20260812 06:19:23.037241 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.051s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17956,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.037817 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:23.051487 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.013s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.052098 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:23.205389 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.153s	user 0.105s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":372,"lbm_read_time_us":9592,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30634,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:19:23.206101 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=11.118625
I20260812 06:19:23.242446 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.036s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15129,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:23.243220 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:23.270207 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.027s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5425,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.270803 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:23.282202 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.283037 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushMRSOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:23.314850 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushMRSOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1520,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2071,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:23.315699 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling LogGCOp(a4656e26278548e7bc763541a5f10e2a): free 129773835 bytes of WAL
I20260812 06:19:23.315958 23361 log_reader.cc:385] T a4656e26278548e7bc763541a5f10e2a: removed 13 log segments from log reader
I20260812 06:19:23.316006 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000027 (ops 129-133)
I20260812 06:19:23.316036 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000028 (ops 134-138)
I20260812 06:19:23.316089 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000029 (ops 139-143)
I20260812 06:19:23.316138 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000030 (ops 144-148)
I20260812 06:19:23.316159 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000031 (ops 149-152)
I20260812 06:19:23.316219 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000032 (ops 153-157)
I20260812 06:19:23.316272 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000033 (ops 158-162)
I20260812 06:19:23.316309 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000034 (ops 163-167)
I20260812 06:19:23.316367 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000035 (ops 168-172)
I20260812 06:19:23.316406 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000036 (ops 173-177)
I20260812 06:19:23.316442 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000037 (ops 178-182)
I20260812 06:19:23.316481 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000038 (ops 183-187)
I20260812 06:19:23.316521 23361 log.cc:1079] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: Deleting log segment in path: /tmp/dist-test-taskvFDOD7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515552921018-22894-0/minicluster-data/ts-0-root/wals/a4656e26278548e7bc763541a5f10e2a/wal-000000039 (ops 188-192)
I20260812 06:19:23.344036 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: LogGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:23.344458 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=3.181125
I20260812 06:19:23.374886 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.030s	user 0.010s	sys 0.015s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7517,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:23.375535 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a): 492 bytes on disk
I20260812 06:19:23.375975 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: UndoDeltaBlockGCOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.376500 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=2.188937
I20260812 06:19:23.386430 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3768,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.386863 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a): perf score=1.000000
I20260812 06:19:23.538379 22894 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.895s	user 1.784s	sys 0.181s
I20260812 06:19:23.602136 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: MajorDeltaCompactionOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.215s	user 0.162s	sys 0.051s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16400,"lbm_reads_lt_1ms":771,"lbm_write_time_us":35910,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3500}
I20260812 06:19:23.602620 23446 maintenance_manager.cc:419] P e3e781739cd64e4f8b0b050732b6cd4c: Scheduling FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a): perf score=10.126437
I20260812 06:19:23.637282 22894 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.006s	sys 0.000s
I20260812 06:19:23.638029 22894 tablet_server.cc:179] TabletServer@127.22.91.129:0 shutting down...
I20260812 06:19:23.643291 23361 maintenance_manager.cc:643] P e3e781739cd64e4f8b0b050732b6cd4c: FlushDeltaMemStoresOp(a4656e26278548e7bc763541a5f10e2a) complete. Timing: real 0.040s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16965,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.643903 22894 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:23.644249 22894 tablet_replica.cc:333] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c: stopping tablet replica
I20260812 06:19:23.644594 22894 raft_consensus.cc:2243] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:23.656754 22894 raft_consensus.cc:2272] T a4656e26278548e7bc763541a5f10e2a P e3e781739cd64e4f8b0b050732b6cd4c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:23.671962 22894 tablet_server.cc:196] TabletServer@127.22.91.129:0 shutdown complete.
I20260812 06:19:23.674919 22894 master.cc:562] Master@127.22.91.190:36147 shutting down...
I20260812 06:19:23.678696 22894 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:23.678902 22894 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:23.678980 22894 tablet_replica.cc:333] T 00000000000000000000000000000000 P c064f35075394a5c9e8549f22847c558: stopping tablet replica
I20260812 06:19:23.692132 22894 master.cc:584] Master@127.22.91.190:36147 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5542 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11041 ms total)

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