[==========] 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:16:37.759742 22046 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.135.190:34497
I20260812 06:16:37.760612 22046 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:16:37.761129 22046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:37.766757 22046 server_base.cc:1061] running on GCE node
W20260812 06:16:37.766881 22064 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:16:37.766948 22061 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:16:37.767084 22060 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:16:37.767545 22046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.767634 22046 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:16:37.767675 22046 hybrid_clock.cc:648] HybridClock initialized: now 1786515397767673 us; error 0 us; skew 500 ppm
I20260812 06:16:37.769173 22046 webserver.cc:533] Webserver started at http://127.21.135.190:43569/ using document root <none> and password file <none>
I20260812 06:16:37.769608 22046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.769663 22046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.769850 22046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.771294 22046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/master-0-root/instance:
uuid: "049a4240730a4f3c845ceffed0107a3b"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-bqcl"
I20260812 06:16:37.774315 22046 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:16:37.776142 22072 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:16:37.777040 22046 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.777136 22046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/master-0-root
uuid: "049a4240730a4f3c845ceffed0107a3b"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-bqcl"
I20260812 06:16:37.777211 22046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-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:16:37.804466 22046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.804952 22046 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:16:37.805094 22046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.812026 22046 rpc_server.cc:307] RPC server started. Bound to: 127.21.135.190:34497
I20260812 06:16:37.812037 22162 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.135.190:34497 every 8 connection(s)
I20260812 06:16:37.813997 22164 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:16:37.819098 22164 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b: Bootstrap starting.
I20260812 06:16:37.821251 22164 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.822096 22164 log.cc:826] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:37.823591 22164 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b: No bootstrap required, opened a new log
I20260812 06:16:37.826298 22164 raft_consensus.cc:359] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "049a4240730a4f3c845ceffed0107a3b" member_type: VOTER }
I20260812 06:16:37.826453 22164 raft_consensus.cc:385] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.826524 22164 raft_consensus.cc:740] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 049a4240730a4f3c845ceffed0107a3b, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.827054 22164 consensus_queue.cc:260] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [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: "049a4240730a4f3c845ceffed0107a3b" member_type: VOTER }
I20260812 06:16:37.827196 22164 raft_consensus.cc:399] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.827270 22164 raft_consensus.cc:493] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.827395 22164 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.828115 22164 raft_consensus.cc:515] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "049a4240730a4f3c845ceffed0107a3b" member_type: VOTER }
I20260812 06:16:37.828505 22164 leader_election.cc:304] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [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: 049a4240730a4f3c845ceffed0107a3b; no voters: 
I20260812 06:16:37.828780 22164 leader_election.cc:290] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.828866 22167 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.829064 22167 raft_consensus.cc:697] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 1 LEADER]: Becoming Leader. State: Replica: 049a4240730a4f3c845ceffed0107a3b, State: Running, Role: LEADER
I20260812 06:16:37.829422 22167 consensus_queue.cc:237] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [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: "049a4240730a4f3c845ceffed0107a3b" member_type: VOTER }
I20260812 06:16:37.829681 22164 sys_catalog.cc:565] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:37.831099 22169 sys_catalog.cc:455] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "049a4240730a4f3c845ceffed0107a3b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "049a4240730a4f3c845ceffed0107a3b" member_type: VOTER } }
I20260812 06:16:37.831233 22169 sys_catalog.cc:458] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:37.831588 22180 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:37.831924 22170 sys_catalog.cc:455] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 049a4240730a4f3c845ceffed0107a3b. Latest consensus state: current_term: 1 leader_uuid: "049a4240730a4f3c845ceffed0107a3b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "049a4240730a4f3c845ceffed0107a3b" member_type: VOTER } }
I20260812 06:16:37.832016 22170 sys_catalog.cc:458] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:37.833627 22180 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:37.833899 22046 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:37.837828 22180 catalog_manager.cc:1383] Generated new cluster ID: 7e9f9d27dbe54c5e983854f509be5094
I20260812 06:16:37.837885 22180 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:37.854401 22180 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:37.855379 22180 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:37.868762 22180 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b: Generated new TSK 0
I20260812 06:16:37.869323 22180 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:37.898449 22046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:37.900851 22214 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:16:37.900836 22224 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:16:37.900826 22213 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:16:37.901270 22046 server_base.cc:1061] running on GCE node
I20260812 06:16:37.901418 22046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.901455 22046 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:16:37.901469 22046 hybrid_clock.cc:648] HybridClock initialized: now 1786515397901469 us; error 0 us; skew 500 ppm
I20260812 06:16:37.902314 22046 webserver.cc:533] Webserver started at http://127.21.135.129:44145/ using document root <none> and password file <none>
I20260812 06:16:37.902467 22046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.902520 22046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.902592 22046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.902920 22046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/instance:
uuid: "d1f933236b7c4a5bb305773e0882fdae"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-bqcl"
I20260812 06:16:37.904244 22046 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:37.905119 22231 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:16:37.905377 22046 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:37.905445 22046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root
uuid: "d1f933236b7c4a5bb305773e0882fdae"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-bqcl"
I20260812 06:16:37.905519 22046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-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:16:37.917858 22046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.918253 22046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.918656 22046 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:37.919410 22046 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:37.919461 22046 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.919514 22046 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:37.919546 22046 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.925427 22046 rpc_server.cc:307] RPC server started. Bound to: 127.21.135.129:46081
I20260812 06:16:37.925482 22336 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.135.129:46081 every 8 connection(s)
I20260812 06:16:37.934588 22337 heartbeater.cc:344] Connected to a master server at 127.21.135.190:34497
I20260812 06:16:37.934796 22337 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:37.935169 22337 heartbeater.cc:507] Master 127.21.135.190:34497 requested a full tablet report, sending...
I20260812 06:16:37.936412 22100 ts_manager.cc:194] Registered new tserver with Master: d1f933236b7c4a5bb305773e0882fdae (127.21.135.129:46081)
I20260812 06:16:37.937110 22046 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011126574s
I20260812 06:16:37.937678 22100 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36496
I20260812 06:16:37.946570 22100 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36498:
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:16:37.959851 22274 tablet_service.cc:1511] Processing CreateTablet for tablet f52d5e87fa3e4b6096abcc9523d1dacb (DEFAULT_TABLE table=heavy-update-compaction-test [id=54d16b5105bd4f56bcfa2446562b4d26]), partition=
I20260812 06:16:37.960237 22274 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f52d5e87fa3e4b6096abcc9523d1dacb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:37.962498 22359 tablet_bootstrap.cc:492] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Bootstrap starting.
I20260812 06:16:37.963387 22359 tablet_bootstrap.cc:654] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.964484 22359 tablet_bootstrap.cc:492] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: No bootstrap required, opened a new log
I20260812 06:16:37.964619 22359 ts_tablet_manager.cc:1403] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.965029 22359 raft_consensus.cc:359] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1f933236b7c4a5bb305773e0882fdae" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 46081 } }
I20260812 06:16:37.965119 22359 raft_consensus.cc:385] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.965142 22359 raft_consensus.cc:740] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d1f933236b7c4a5bb305773e0882fdae, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.965258 22359 consensus_queue.cc:260] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [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: "d1f933236b7c4a5bb305773e0882fdae" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 46081 } }
I20260812 06:16:37.965341 22359 raft_consensus.cc:399] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.965377 22359 raft_consensus.cc:493] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.965426 22359 raft_consensus.cc:3060] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.966192 22359 raft_consensus.cc:515] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1f933236b7c4a5bb305773e0882fdae" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 46081 } }
I20260812 06:16:37.966311 22359 leader_election.cc:304] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [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: d1f933236b7c4a5bb305773e0882fdae; no voters: 
I20260812 06:16:37.966487 22359 leader_election.cc:290] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.966626 22365 raft_consensus.cc:2804] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.966802 22359 ts_tablet_manager.cc:1434] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.966902 22365 raft_consensus.cc:697] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 1 LEADER]: Becoming Leader. State: Replica: d1f933236b7c4a5bb305773e0882fdae, State: Running, Role: LEADER
I20260812 06:16:37.966961 22337 heartbeater.cc:499] Master 127.21.135.190:34497 was elected leader, sending a full tablet report...
I20260812 06:16:37.967370 22365 consensus_queue.cc:237] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [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: "d1f933236b7c4a5bb305773e0882fdae" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 46081 } }
I20260812 06:16:37.969925 22100 catalog_manager.cc:5719] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae reported cstate change: term changed from 0 to 1, leader changed from <none> to d1f933236b7c4a5bb305773e0882fdae (127.21.135.129). New cstate: current_term: 1 leader_uuid: "d1f933236b7c4a5bb305773e0882fdae" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1f933236b7c4a5bb305773e0882fdae" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 46081 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:38.029103 22046 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.009s
I20260812 06:16:38.176460 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=22.031503
I20260812 06:16:38.376179 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.199s	user 0.138s	sys 0.059s Metrics: {"bytes_written":16409902,"cfile_init":1,"compiler_manager_pool.queue_time_us":187,"delete_count":0,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":859,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":51874,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":122,"threads_started":1,"update_count":2000}
I20260812 06:16:38.377408 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): free 20743880 bytes of WAL
I20260812 06:16:38.377723 22237 log_reader.cc:385] T f52d5e87fa3e4b6096abcc9523d1dacb: removed 2 log segments from log reader
I20260812 06:16:38.377797 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000001 (ops 1-6)
I20260812 06:16:38.377857 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000002 (ops 7-11)
I20260812 06:16:38.383397 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:38.383733 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=3.181125
I20260812 06:16:38.397599 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5507,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:38.397998 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:38.410280 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4861,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:38.410686 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:38.593475 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.183s	user 0.122s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":874,"lbm_read_time_us":11205,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30428,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":287,"threads_started":5,"update_count":3000}
I20260812 06:16:38.594035 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): 20513812 bytes on disk
I20260812 06:16:38.594523 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:38.594964 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:38.643805 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.049s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21801,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.644299 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:38.786933 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.142s	user 0.086s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":68,"lbm_read_time_us":10661,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23384,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31616,"update_count":2000}
I20260812 06:16:38.792512 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=11.118625
I20260812 06:16:38.822054 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.029s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12277,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:38.822526 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:38.836158 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5126,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:38.836735 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:38.948843 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.112s	user 0.072s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":692,"lbm_read_time_us":6715,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21215,"lbm_writes_lt_1ms":443,"mutex_wait_us":301,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:16:38.949385 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:38.995002 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.045s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14731,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.995564 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:39.005329 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.005812 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:39.127625 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.122s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":651,"lbm_read_time_us":7526,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20827,"lbm_writes_lt_1ms":443,"mutex_wait_us":345,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2000}
I20260812 06:16:39.128233 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:39.161118 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.033s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14047,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.161615 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:39.171144 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.171557 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:39.285616 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.114s	user 0.073s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1011,"lbm_read_time_us":8216,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19734,"lbm_writes_lt_1ms":443,"mutex_wait_us":402,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:16:39.286317 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:39.330642 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.044s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17476,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.331257 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:39.341881 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.342428 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:39.481148 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.139s	user 0.089s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":471,"lbm_read_time_us":11046,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21259,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.481716 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:39.513468 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.032s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12203,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.514094 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:39.527486 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.527894 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:39.552945 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.025s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1151,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1266,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:39.554061 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): free 124257234 bytes of WAL
I20260812 06:16:39.554368 22237 log_reader.cc:385] T f52d5e87fa3e4b6096abcc9523d1dacb: removed 12 log segments from log reader
I20260812 06:16:39.554423 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000003 (ops 12-16)
I20260812 06:16:39.554450 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000004 (ops 17-21)
I20260812 06:16:39.554466 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000005 (ops 22-26)
I20260812 06:16:39.554486 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000006 (ops 27-31)
I20260812 06:16:39.554515 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000007 (ops 32-36)
I20260812 06:16:39.554582 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000008 (ops 37-41)
I20260812 06:16:39.554600 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000009 (ops 42-46)
I20260812 06:16:39.554618 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000010 (ops 47-51)
I20260812 06:16:39.554658 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000011 (ops 52-56)
I20260812 06:16:39.554690 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000012 (ops 57-61)
I20260812 06:16:39.554726 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000013 (ops 62-66)
I20260812 06:16:39.554760 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000014 (ops 67-70)
I20260812 06:16:39.576944 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:16:39.577436 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): 472 bytes on disk
I20260812 06:16:39.577939 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.578474 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=5.165500
I20260812 06:16:39.607919 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.029s	user 0.004s	sys 0.023s Metrics: {"bytes_written":7302545,"delete_count":0,"lbm_write_time_us":10120,"lbm_writes_lt_1ms":181,"reinsert_count":0,"update_count":890}
I20260812 06:16:39.608417 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:39.782941 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.174s	user 0.085s	sys 0.087s Metrics: {"cfile_cache_miss":611,"cfile_cache_miss_bytes":28015683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":652,"lbm_read_time_us":12364,"lbm_reads_lt_1ms":647,"lbm_write_time_us":28819,"lbm_writes_lt_1ms":621,"mutex_wait_us":595,"peak_mem_usage":72558934,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":78,"threads_started":1,"update_count":2890}
I20260812 06:16:39.783416 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=15.087375
I20260812 06:16:39.843888 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.060s	user 0.038s	sys 0.020s Metrics: {"bytes_written":17312442,"delete_count":0,"lbm_write_time_us":22755,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2110}
I20260812 06:16:39.844369 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:39.858831 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.859308 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:40.037351 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.178s	user 0.128s	sys 0.037s Metrics: {"cfile_cache_miss":554,"cfile_cache_miss_bytes":25718224,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1247,"lbm_read_time_us":11470,"lbm_reads_lt_1ms":594,"lbm_write_time_us":27950,"lbm_writes_lt_1ms":565,"mutex_wait_us":419,"peak_mem_usage":65059054,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2610}
I20260812 06:16:40.037864 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:40.090031 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.052s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23321,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.090605 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:40.110047 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.019s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.110571 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:40.286368 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.176s	user 0.142s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":822,"lbm_read_time_us":12198,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29518,"lbm_writes_lt_1ms":543,"mutex_wait_us":249,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:40.286803 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:40.328688 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.042s	user 0.023s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.329130 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:40.339761 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.340190 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:40.496914 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.157s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":611,"lbm_read_time_us":10502,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24560,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:40.497383 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=11.118625
I20260812 06:16:40.525636 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.028s	user 0.016s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":11552,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:40.526304 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:40.539963 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.540540 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:40.662184 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.121s	user 0.098s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":352,"lbm_read_time_us":7867,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22735,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":70784,"update_count":2000}
I20260812 06:16:40.662727 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:40.697533 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.035s	user 0.004s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13160,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.698076 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:40.709353 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.709790 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:40.839365 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.129s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":9268,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26036,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.839974 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:40.888926 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.049s	user 0.023s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15823,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.889436 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:40.899291 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.899682 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:40.928938 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":1238,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1706,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:40.929750 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:41.078987 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.149s	user 0.109s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":9169,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25228,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.079663 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): free 121459505 bytes of WAL
I20260812 06:16:41.079911 22237 log_reader.cc:385] T f52d5e87fa3e4b6096abcc9523d1dacb: removed 12 log segments from log reader
I20260812 06:16:41.079974 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000015 (ops 71-75)
I20260812 06:16:41.080080 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000016 (ops 76-80)
I20260812 06:16:41.080137 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000017 (ops 81-85)
I20260812 06:16:41.080214 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000018 (ops 86-90)
I20260812 06:16:41.080265 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000019 (ops 91-95)
I20260812 06:16:41.080338 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000020 (ops 96-100)
I20260812 06:16:41.080410 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000021 (ops 101-105)
I20260812 06:16:41.080458 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000022 (ops 106-110)
I20260812 06:16:41.080510 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000023 (ops 111-115)
I20260812 06:16:41.080586 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000024 (ops 116-120)
I20260812 06:16:41.080634 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000025 (ops 121-125)
I20260812 06:16:41.080670 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000026 (ops 126-130)
I20260812 06:16:41.103111 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:41.103596 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:41.148553 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.045s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20469,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.149099 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:41.176512 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.027s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.177008 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): 462 bytes on disk
I20260812 06:16:41.177419 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.177947 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:41.194583 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.016s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.195196 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:41.384784 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.189s	user 0.144s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918214,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":178,"lbm_read_time_us":14666,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35601,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:16:41.385383 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:41.437393 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.052s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18948,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.437916 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:41.454464 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.016s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.454962 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:41.633533 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.178s	user 0.138s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":671,"lbm_read_time_us":12394,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28152,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:41.634100 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:41.683670 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.049s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20113,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.684167 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:41.693899 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.694329 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:41.872306 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.178s	user 0.124s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":9477,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28189,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:16:41.873035 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=11.118625
I20260812 06:16:41.900553 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.027s	user 0.017s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11594,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:41.901328 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:41.914183 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.914777 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:42.029754 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.115s	user 0.090s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":7070,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22031,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:16:42.030419 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:42.066584 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.036s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13119,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.067119 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:42.076536 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.077135 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:42.199231 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.122s	user 0.086s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":7567,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21846,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:42.199914 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=10.126437
I20260812 06:16:42.230213 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.030s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13384,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.230723 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:42.253350 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushMRSOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.022s	user 0.021s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1052,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1253,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:42.253947 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): free 112239554 bytes of WAL
I20260812 06:16:42.254182 22237 log_reader.cc:385] T f52d5e87fa3e4b6096abcc9523d1dacb: removed 11 log segments from log reader
I20260812 06:16:42.254228 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000027 (ops 131-134)
I20260812 06:16:42.254257 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000028 (ops 135-139)
I20260812 06:16:42.254287 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000029 (ops 140-144)
I20260812 06:16:42.254319 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000030 (ops 145-149)
I20260812 06:16:42.254351 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000031 (ops 150-154)
I20260812 06:16:42.254384 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000032 (ops 155-159)
I20260812 06:16:42.254416 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000033 (ops 160-164)
I20260812 06:16:42.254448 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000034 (ops 165-169)
I20260812 06:16:42.254482 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000035 (ops 170-174)
I20260812 06:16:42.254511 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000036 (ops 175-179)
I20260812 06:16:42.254540 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000037 (ops 180-184)
I20260812 06:16:42.275743 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.022s	user 0.005s	sys 0.015s Metrics: {}
I20260812 06:16:42.276141 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): 447 bytes on disk
I20260812 06:16:42.276531 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: UndoDeltaBlockGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.277110 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=3.181125
I20260812 06:16:42.288341 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4800079,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:16:42.288748 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:42.297034 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":3125,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:16:42.297385 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb): free 11564893 bytes of WAL
I20260812 06:16:42.297555 22237 log_reader.cc:385] T f52d5e87fa3e4b6096abcc9523d1dacb: removed 1 log segments from log reader
I20260812 06:16:42.297597 22237 log.cc:1079] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/f52d5e87fa3e4b6096abcc9523d1dacb/wal-000000038 (ops 185-188)
I20260812 06:16:42.300056 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: LogGCOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:42.300403 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:42.462682 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.162s	user 0.105s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1554,"lbm_read_time_us":10710,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27418,"lbm_writes_lt_1ms":543,"mutex_wait_us":628,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":71,"threads_started":1,"update_count":2500}
I20260812 06:16:42.463231 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=14.095187
I20260812 06:16:42.528460 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.065s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25878,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.528942 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=2.188937
I20260812 06:16:42.538679 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.539080 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=1.000000
I20260812 06:16:42.608310 22046 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.579s	user 1.669s	sys 0.152s
I20260812 06:16:42.691521 22046 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.083s	user 0.002s	sys 0.000s
I20260812 06:16:42.692134 22046 tablet_server.cc:179] TabletServer@127.21.135.129:0 shutting down...
I20260812 06:16:42.692430 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: MajorDeltaCompactionOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.153s	user 0.121s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":644,"lbm_read_time_us":10161,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28879,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:16:42.693203 22342 maintenance_manager.cc:419] P d1f933236b7c4a5bb305773e0882fdae: Scheduling FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb): perf score=6.157687
I20260812 06:16:42.714051 22237 maintenance_manager.cc:643] P d1f933236b7c4a5bb305773e0882fdae: FlushDeltaMemStoresOp(f52d5e87fa3e4b6096abcc9523d1dacb) complete. Timing: real 0.021s	user 0.015s	sys 0.003s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9059,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.714588 22046 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:42.714979 22046 tablet_replica.cc:333] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae: stopping tablet replica
I20260812 06:16:42.715175 22046 raft_consensus.cc:2243] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:42.715346 22046 raft_consensus.cc:2272] T f52d5e87fa3e4b6096abcc9523d1dacb P d1f933236b7c4a5bb305773e0882fdae [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:42.730427 22046 tablet_server.cc:196] TabletServer@127.21.135.129:0 shutdown complete.
I20260812 06:16:42.737183 22046 master.cc:562] Master@127.21.135.190:34497 shutting down...
I20260812 06:16:42.740386 22046 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:42.740528 22046 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:42.740598 22046 tablet_replica.cc:333] T 00000000000000000000000000000000 P 049a4240730a4f3c845ceffed0107a3b: stopping tablet replica
I20260812 06:16:42.752507 22046 master.cc:584] Master@127.21.135.190:34497 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5062 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:42.830758 22046 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.135.190:34807
I20260812 06:16:42.831125 22046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.833040 22400 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:16:42.833129 22403 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:16:42.833081 22046 server_base.cc:1061] running on GCE node
W20260812 06:16:42.833072 22399 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:16:42.833447 22046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.833487 22046 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:16:42.833501 22046 hybrid_clock.cc:648] HybridClock initialized: now 1786515402833501 us; error 0 us; skew 500 ppm
I20260812 06:16:42.834270 22046 webserver.cc:533] Webserver started at http://127.21.135.190:46209/ using document root <none> and password file <none>
I20260812 06:16:42.834404 22046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.834442 22046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.834496 22046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.834810 22046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/master-0-root/instance:
uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-bqcl"
I20260812 06:16:42.836150 22046 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:42.836933 22412 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:16:42.837155 22046 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:42.837224 22046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/master-0-root
uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-bqcl"
I20260812 06:16:42.837288 22046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-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:16:42.847615 22046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.847903 22046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.851826 22046 rpc_server.cc:307] RPC server started. Bound to: 127.21.135.190:34807
I20260812 06:16:42.856172 22523 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.135.190:34807 every 8 connection(s)
I20260812 06:16:42.856575 22524 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:16:42.858197 22524 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7: Bootstrap starting.
I20260812 06:16:42.858911 22524 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.859759 22524 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7: No bootstrap required, opened a new log
I20260812 06:16:42.860101 22524 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7" member_type: VOTER }
I20260812 06:16:42.860178 22524 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.860203 22524 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2d81f2c9869349a89c5b4a7c8e12a3b7, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.860306 22524 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [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: "2d81f2c9869349a89c5b4a7c8e12a3b7" member_type: VOTER }
I20260812 06:16:42.860358 22524 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.860383 22524 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.860412 22524 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.861007 22524 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7" member_type: VOTER }
I20260812 06:16:42.861122 22524 leader_election.cc:304] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [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: 2d81f2c9869349a89c5b4a7c8e12a3b7; no voters: 
I20260812 06:16:42.861260 22524 leader_election.cc:290] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.861375 22530 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.861585 22530 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 1 LEADER]: Becoming Leader. State: Replica: 2d81f2c9869349a89c5b4a7c8e12a3b7, State: Running, Role: LEADER
I20260812 06:16:42.861675 22524 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:42.861721 22530 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [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: "2d81f2c9869349a89c5b4a7c8e12a3b7" member_type: VOTER }
I20260812 06:16:42.862141 22535 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2d81f2c9869349a89c5b4a7c8e12a3b7. Latest consensus state: current_term: 1 leader_uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7" member_type: VOTER } }
I20260812 06:16:42.862242 22535 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.862110 22534 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d81f2c9869349a89c5b4a7c8e12a3b7" member_type: VOTER } }
I20260812 06:16:42.862438 22534 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.862545 22542 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:42.863215 22542 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:42.863476 22046 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:42.864938 22542 catalog_manager.cc:1383] Generated new cluster ID: cdaec824b86b4c158926b45f6883ac2a
I20260812 06:16:42.865000 22542 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:42.882208 22542 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:42.882704 22542 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:42.892215 22542 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7: Generated new TSK 0
I20260812 06:16:42.892349 22542 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:42.895556 22046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.897392 22558 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:16:42.897519 22564 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:16:42.897585 22046 server_base.cc:1061] running on GCE node
W20260812 06:16:42.897490 22557 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:16:42.897855 22046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.897902 22046 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:16:42.897915 22046 hybrid_clock.cc:648] HybridClock initialized: now 1786515402897916 us; error 0 us; skew 500 ppm
I20260812 06:16:42.898710 22046 webserver.cc:533] Webserver started at http://127.21.135.129:44885/ using document root <none> and password file <none>
I20260812 06:16:42.898841 22046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.898895 22046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.898962 22046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.899288 22046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/instance:
uuid: "fbae25743ba1417fa1e07582ad8b01c6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-bqcl"
I20260812 06:16:42.900563 22046 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:42.901367 22573 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:16:42.901593 22046 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:42.901657 22046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root
uuid: "fbae25743ba1417fa1e07582ad8b01c6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-bqcl"
I20260812 06:16:42.901716 22046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-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:16:42.933831 22046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.934262 22046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.934552 22046 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:42.935005 22046 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:42.935043 22046 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.935086 22046 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:42.935113 22046 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.938956 22046 rpc_server.cc:307] RPC server started. Bound to: 127.21.135.129:33061
I20260812 06:16:42.939853 22700 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.135.129:33061 every 8 connection(s)
I20260812 06:16:42.949362 22705 heartbeater.cc:344] Connected to a master server at 127.21.135.190:34807
I20260812 06:16:42.949463 22705 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:42.949687 22705 heartbeater.cc:507] Master 127.21.135.190:34807 requested a full tablet report, sending...
I20260812 06:16:42.950328 22442 ts_manager.cc:194] Registered new tserver with Master: fbae25743ba1417fa1e07582ad8b01c6 (127.21.135.129:33061)
I20260812 06:16:42.950671 22046 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011068442s
I20260812 06:16:42.951052 22442 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54188
I20260812 06:16:42.957185 22442 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54198:
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:16:42.965413 22634 tablet_service.cc:1511] Processing CreateTablet for tablet ac6263a28bce4e9bb033f1bce69d4d79 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b6423cf92e064c3ab42c84a82ea995ad]), partition=
I20260812 06:16:42.965669 22634 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ac6263a28bce4e9bb033f1bce69d4d79. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:42.967573 22732 tablet_bootstrap.cc:492] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Bootstrap starting.
I20260812 06:16:42.968406 22732 tablet_bootstrap.cc:654] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.969375 22732 tablet_bootstrap.cc:492] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: No bootstrap required, opened a new log
I20260812 06:16:42.969457 22732 ts_tablet_manager.cc:1403] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:42.969854 22732 raft_consensus.cc:359] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbae25743ba1417fa1e07582ad8b01c6" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 33061 } }
I20260812 06:16:42.969942 22732 raft_consensus.cc:385] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.969973 22732 raft_consensus.cc:740] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fbae25743ba1417fa1e07582ad8b01c6, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.970109 22732 consensus_queue.cc:260] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [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: "fbae25743ba1417fa1e07582ad8b01c6" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 33061 } }
I20260812 06:16:42.970229 22732 raft_consensus.cc:399] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.970265 22732 raft_consensus.cc:493] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.970314 22732 raft_consensus.cc:3060] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.971094 22732 raft_consensus.cc:515] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbae25743ba1417fa1e07582ad8b01c6" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 33061 } }
I20260812 06:16:42.971223 22732 leader_election.cc:304] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [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: fbae25743ba1417fa1e07582ad8b01c6; no voters: 
I20260812 06:16:42.971398 22732 leader_election.cc:290] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.971506 22734 raft_consensus.cc:2804] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.971683 22734 raft_consensus.cc:697] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 1 LEADER]: Becoming Leader. State: Replica: fbae25743ba1417fa1e07582ad8b01c6, State: Running, Role: LEADER
I20260812 06:16:42.971702 22732 ts_tablet_manager.cc:1434] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:42.971725 22705 heartbeater.cc:499] Master 127.21.135.190:34807 was elected leader, sending a full tablet report...
I20260812 06:16:42.971827 22734 consensus_queue.cc:237] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [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: "fbae25743ba1417fa1e07582ad8b01c6" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 33061 } }
I20260812 06:16:42.973058 22442 catalog_manager.cc:5719] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 reported cstate change: term changed from 0 to 1, leader changed from <none> to fbae25743ba1417fa1e07582ad8b01c6 (127.21.135.129). New cstate: current_term: 1 leader_uuid: "fbae25743ba1417fa1e07582ad8b01c6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbae25743ba1417fa1e07582ad8b01c6" member_type: VOTER last_known_addr { host: "127.21.135.129" port: 33061 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:43.027573 22046 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.008s
I20260812 06:16:43.190339 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=23.023690
I20260812 06:16:43.353781 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.163s	user 0.119s	sys 0.040s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":812,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41592,"lbm_writes_lt_1ms":867,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1550}
I20260812 06:16:43.354382 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79): free 20743880 bytes of WAL
I20260812 06:16:43.354605 22581 log_reader.cc:385] T ac6263a28bce4e9bb033f1bce69d4d79: removed 2 log segments from log reader
I20260812 06:16:43.354657 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000001 (ops 1-6)
I20260812 06:16:43.354686 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000002 (ops 7-11)
I20260812 06:16:43.360351 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:43.360702 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79): 20513814 bytes on disk
I20260812 06:16:43.361161 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.361562 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:43.377879 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4125,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.378285 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:43.391850 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.392256 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:43.562676 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.170s	user 0.121s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":781,"lbm_read_time_us":11261,"lbm_reads_lt_1ms":569,"lbm_write_time_us":24880,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":346,"threads_started":5,"update_count":2500}
I20260812 06:16:43.563246 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:43.613853 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.050s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22679,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.614357 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:43.752096 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.138s	user 0.099s	sys 0.030s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":206,"lbm_read_time_us":9062,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21707,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:16:43.752570 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:43.799664 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.047s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17587,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.800187 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:43.810840 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.811326 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:43.975467 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.164s	user 0.093s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":10613,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24238,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:16:43.975983 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:44.028088 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.052s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24986,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.028695 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.044269 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.045001 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:44.195952 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.151s	user 0.118s	sys 0.026s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":558,"lbm_read_time_us":8037,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27091,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:16:44.196506 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:44.245362 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.049s	user 0.015s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.245903 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.256381 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.256798 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:44.397655 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.141s	user 0.114s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":433,"lbm_read_time_us":10396,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27055,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:16:44.398299 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=11.118625
I20260812 06:16:44.431412 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.033s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13918,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:44.432008 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.454273 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.022s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4827,"lbm_writes_lt_1ms":93,"mutex_wait_us":2,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.454810 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.464488 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.465055 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:44.496721 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.031s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1134,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1897,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:44.497368 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79): free 120553321 bytes of WAL
I20260812 06:16:44.497606 22581 log_reader.cc:385] T ac6263a28bce4e9bb033f1bce69d4d79: removed 12 log segments from log reader
I20260812 06:16:44.497658 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000003 (ops 12-16)
I20260812 06:16:44.497696 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000004 (ops 17-21)
I20260812 06:16:44.497730 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000005 (ops 22-26)
I20260812 06:16:44.497757 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000006 (ops 27-31)
I20260812 06:16:44.497788 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000007 (ops 32-36)
I20260812 06:16:44.497819 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000008 (ops 37-41)
I20260812 06:16:44.497849 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000009 (ops 42-46)
I20260812 06:16:44.497880 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000010 (ops 47-50)
I20260812 06:16:44.497910 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000011 (ops 51-55)
I20260812 06:16:44.497941 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000012 (ops 56-60)
I20260812 06:16:44.497972 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000013 (ops 61-64)
I20260812 06:16:44.498001 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000014 (ops 65-69)
I20260812 06:16:44.517704 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:16:44.518168 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79): 462 bytes on disk
I20260812 06:16:44.518556 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.518980 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.533551 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.533953 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.544298 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.544659 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:44.764837 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.220s	user 0.139s	sys 0.065s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020855,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":119,"lbm_read_time_us":12958,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36063,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:16:44.765398 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=18.063937
I20260812 06:16:44.829435 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.064s	user 0.035s	sys 0.026s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23622,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.830020 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:44.844648 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.845148 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:45.032608 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.187s	user 0.139s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":168,"lbm_read_time_us":12772,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30377,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":3000}
I20260812 06:16:45.033185 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:45.080289 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.047s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18917,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.080825 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:45.090924 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3920,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.091454 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:45.253624 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.162s	user 0.092s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":12316,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25038,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.254109 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:45.313642 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.059s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24250,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.314265 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:45.324450 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.325078 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:45.484669 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.159s	user 0.097s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":11611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25830,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:16:45.485190 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=11.118625
I20260812 06:16:45.522116 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.037s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15213,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:45.522639 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:45.545413 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.545871 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:45.555086 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3545,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.555625 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:45.721508 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.166s	user 0.113s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1158,"dirs.run_cpu_time_us":510,"dirs.run_wall_time_us":3790,"lbm_read_time_us":11930,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25578,"lbm_writes_lt_1ms":543,"mutex_wait_us":519,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:16:45.722347 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=11.118625
I20260812 06:16:45.768543 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.046s	user 0.028s	sys 0.008s Metrics: {"bytes_written":13456166,"delete_count":0,"lbm_write_time_us":16961,"lbm_writes_lt_1ms":331,"reinsert_count":0,"update_count":1640}
I20260812 06:16:45.768981 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:45.780195 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.011s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3364209,"delete_count":0,"lbm_write_time_us":2982,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:16:45.780606 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:45.796931 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.016s	user 0.007s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3140,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.797319 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:45.828724 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.031s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1180,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1598,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:45.829526 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79): 447 bytes on disk
I20260812 06:16:45.830037 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.830724 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:45.982911 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.152s	user 0.124s	sys 0.027s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815775,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":170,"lbm_read_time_us":11655,"lbm_reads_lt_1ms":565,"lbm_write_time_us":23339,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:16:45.983842 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79): free 112692422 bytes of WAL
I20260812 06:16:45.984324 22581 log_reader.cc:385] T ac6263a28bce4e9bb033f1bce69d4d79: removed 11 log segments from log reader
I20260812 06:16:45.984395 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000015 (ops 70-74)
I20260812 06:16:45.984519 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000016 (ops 75-79)
I20260812 06:16:45.984575 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000017 (ops 80-84)
I20260812 06:16:45.984648 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000018 (ops 85-89)
I20260812 06:16:45.984696 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000019 (ops 90-94)
I20260812 06:16:45.984726 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000020 (ops 95-99)
I20260812 06:16:45.984762 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000021 (ops 100-104)
I20260812 06:16:45.984799 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000022 (ops 105-109)
I20260812 06:16:45.984838 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000023 (ops 110-114)
I20260812 06:16:45.984874 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000024 (ops 115-119)
I20260812 06:16:45.984910 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000025 (ops 120-124)
I20260812 06:16:46.007416 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:46.007788 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=15.087375
I20260812 06:16:46.054656 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.047s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":20323,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:46.055176 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79): free 11564885 bytes of WAL
I20260812 06:16:46.055408 22581 log_reader.cc:385] T ac6263a28bce4e9bb033f1bce69d4d79: removed 1 log segments from log reader
I20260812 06:16:46.055461 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000026 (ops 125-128)
I20260812 06:16:46.057432 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:46.057797 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:46.079146 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.021s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.079572 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:46.088583 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.089000 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:46.279690 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.190s	user 0.134s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2360,"lbm_read_time_us":13094,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31275,"lbm_writes_lt_1ms":643,"mutex_wait_us":968,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:16:46.280352 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:46.333323 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.053s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18541,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.333853 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:46.347617 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.348013 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:46.532474 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.184s	user 0.137s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1224,"lbm_read_time_us":12497,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27734,"lbm_writes_lt_1ms":543,"mutex_wait_us":394,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:16:46.532998 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:46.592234 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.059s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23166,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.592886 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:46.609823 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.610350 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:46.784943 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.174s	user 0.131s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":101,"lbm_read_time_us":13097,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29922,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:16:46.785506 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=11.118625
I20260812 06:16:46.813531 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.028s	user 0.022s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11805,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:46.814185 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:46.841096 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.027s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6987,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.841625 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:46.856976 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.857563 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:47.031502 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.174s	user 0.108s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":169,"lbm_read_time_us":10269,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28097,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:16:47.032056 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:47.079329 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.047s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.079833 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:47.095255 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.095813 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:47.231129 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.135s	user 0.100s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":8388,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25360,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":56704,"update_count":2500}
I20260812 06:16:47.231775 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=10.126437
I20260812 06:16:47.260896 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.029s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12856,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.261642 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:47.291970 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.030s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.292510 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:47.305408 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.305922 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:47.333189 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushMRSOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.027s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1141,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1536,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:47.333916 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79): free 120553636 bytes of WAL
I20260812 06:16:47.334175 22581 log_reader.cc:385] T ac6263a28bce4e9bb033f1bce69d4d79: removed 12 log segments from log reader
I20260812 06:16:47.334230 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000027 (ops 129-133)
I20260812 06:16:47.334277 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000028 (ops 134-138)
I20260812 06:16:47.334308 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000029 (ops 139-142)
I20260812 06:16:47.334340 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000030 (ops 143-147)
I20260812 06:16:47.334371 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000031 (ops 148-152)
I20260812 06:16:47.334401 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000032 (ops 153-157)
I20260812 06:16:47.334431 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000033 (ops 158-162)
I20260812 06:16:47.334460 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000034 (ops 163-167)
I20260812 06:16:47.334499 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000035 (ops 168-172)
I20260812 06:16:47.334530 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000036 (ops 173-177)
I20260812 06:16:47.334559 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000037 (ops 178-182)
I20260812 06:16:47.334590 22581 log.cc:1079] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: Deleting log segment in path: /tmp/dist-test-taskggdZ1V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397749607-22046-0/minicluster-data/ts-0-root/wals/ac6263a28bce4e9bb033f1bce69d4d79/wal-000000038 (ops 183-186)
I20260812 06:16:47.355268 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: LogGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.021s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:16:47.355684 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79): 482 bytes on disk
I20260812 06:16:47.356087 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: UndoDeltaBlockGCOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.356606 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=3.181125
I20260812 06:16:47.384181 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.027s	user 0.008s	sys 0.014s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6639,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:47.384546 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:47.393342 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3387,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.393680 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:47.593189 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.199s	user 0.127s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":520,"lbm_read_time_us":13732,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34711,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:16:47.596673 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=14.095187
I20260812 06:16:47.634948 22046 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.599s	user 1.650s	sys 0.195s
I20260812 06:16:47.637729 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.041s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":17989,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.638296 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=2.188937
I20260812 06:16:47.649540 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: FlushDeltaMemStoresOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.649988 22711 maintenance_manager.cc:419] P fbae25743ba1417fa1e07582ad8b01c6: Scheduling MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79): perf score=1.000000
I20260812 06:16:47.673750 22046 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.038s	user 0.001s	sys 0.000s
I20260812 06:16:47.674250 22046 tablet_server.cc:179] TabletServer@127.21.135.129:0 shutting down...
I20260812 06:16:47.779109 22581 maintenance_manager.cc:643] P fbae25743ba1417fa1e07582ad8b01c6: MajorDeltaCompactionOp(ac6263a28bce4e9bb033f1bce69d4d79) complete. Timing: real 0.129s	user 0.093s	sys 0.036s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512302,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":7204,"lbm_reads_lt_1ms":518,"lbm_write_time_us":21578,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:16:47.779778 22046 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.780048 22046 tablet_replica.cc:333] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6: stopping tablet replica
I20260812 06:16:47.780182 22046 raft_consensus.cc:2243] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.780346 22046 raft_consensus.cc:2272] T ac6263a28bce4e9bb033f1bce69d4d79 P fbae25743ba1417fa1e07582ad8b01c6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.794626 22046 tablet_server.cc:196] TabletServer@127.21.135.129:0 shutdown complete.
I20260812 06:16:47.823530 22046 master.cc:562] Master@127.21.135.190:34807 shutting down...
I20260812 06:16:47.826557 22046 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.826711 22046 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.826787 22046 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2d81f2c9869349a89c5b4a7c8e12a3b7: stopping tablet replica
I20260812 06:16:47.838654 22046 master.cc:584] Master@127.21.135.190:34807 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5086 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10149 ms total)

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