[==========] 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:24.196105  4343 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.61.254:38945
I20260812 06:16:24.197352  4343 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:24.198037  4343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:24.205468  4348 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:24.205493  4350 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:24.205603  4343 server_base.cc:1061] running on GCE node
W20260812 06:16:24.205812  4353 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:24.206318  4343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:24.206483  4343 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:24.206559  4343 hybrid_clock.cc:648] HybridClock initialized: now 1786515384206556 us; error 0 us; skew 500 ppm
I20260812 06:16:24.208536  4343 webserver.cc:533] Webserver started at http://127.4.61.254:43045/ using document root <none> and password file <none>
I20260812 06:16:24.209201  4343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:24.209306  4343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:24.209623  4343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:24.211340  4343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/master-0-root/instance:
uuid: "113980f842a74d2798fdbd459ec7a308"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-3h5h"
I20260812 06:16:24.215224  4343 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.004s
I20260812 06:16:24.217469  4361 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:24.218590  4343 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:16:24.218753  4343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/master-0-root
uuid: "113980f842a74d2798fdbd459ec7a308"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-3h5h"
I20260812 06:16:24.218887  4343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-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:24.244658  4343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:24.245585  4343 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:24.245806  4343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:24.260610  4343 rpc_server.cc:307] RPC server started. Bound to: 127.4.61.254:38945
I20260812 06:16:24.260643  4439 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.61.254:38945 every 8 connection(s)
I20260812 06:16:24.263149  4441 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:24.268802  4441 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: Bootstrap starting.
I20260812 06:16:24.271219  4441 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:24.272181  4441 log.cc:826] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:24.274196  4441 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: No bootstrap required, opened a new log
I20260812 06:16:24.277086  4441 raft_consensus.cc:359] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "113980f842a74d2798fdbd459ec7a308" member_type: VOTER }
I20260812 06:16:24.277262  4441 raft_consensus.cc:385] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:24.277314  4441 raft_consensus.cc:740] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 113980f842a74d2798fdbd459ec7a308, State: Initialized, Role: FOLLOWER
I20260812 06:16:24.278079  4441 consensus_queue.cc:260] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [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: "113980f842a74d2798fdbd459ec7a308" member_type: VOTER }
I20260812 06:16:24.278232  4441 raft_consensus.cc:399] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:24.278327  4441 raft_consensus.cc:493] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:24.278506  4441 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:24.279362  4441 raft_consensus.cc:515] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "113980f842a74d2798fdbd459ec7a308" member_type: VOTER }
I20260812 06:16:24.279832  4441 leader_election.cc:304] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [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: 113980f842a74d2798fdbd459ec7a308; no voters: 
I20260812 06:16:24.280170  4441 leader_election.cc:290] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:24.280462  4449 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:24.280827  4449 raft_consensus.cc:697] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 1 LEADER]: Becoming Leader. State: Replica: 113980f842a74d2798fdbd459ec7a308, State: Running, Role: LEADER
I20260812 06:16:24.281424  4441 sys_catalog.cc:565] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:24.281427  4449 consensus_queue.cc:237] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [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: "113980f842a74d2798fdbd459ec7a308" member_type: VOTER }
I20260812 06:16:24.283743  4343 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:24.284147  4451 sys_catalog.cc:455] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 113980f842a74d2798fdbd459ec7a308. Latest consensus state: current_term: 1 leader_uuid: "113980f842a74d2798fdbd459ec7a308" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "113980f842a74d2798fdbd459ec7a308" member_type: VOTER } }
I20260812 06:16:24.284158  4450 sys_catalog.cc:455] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "113980f842a74d2798fdbd459ec7a308" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "113980f842a74d2798fdbd459ec7a308" member_type: VOTER } }
I20260812 06:16:24.284262  4451 sys_catalog.cc:458] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:24.284284  4450 sys_catalog.cc:458] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [sys.catalog]: This master's current role is: LEADER
W20260812 06:16:24.286088  4474 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:24.286180  4474 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:24.286301  4475 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:24.287372  4475 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:24.293660  4475 catalog_manager.cc:1383] Generated new cluster ID: ceb409874ed64f8f8c98fbe1515f66c4
I20260812 06:16:24.293787  4475 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:24.300540  4475 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:24.302196  4475 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:24.328711  4475 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: Generated new TSK 0
I20260812 06:16:24.329698  4475 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:24.348908  4343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:24.352604  4480 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:24.352720  4486 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:24.353024  4481 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:24.353726  4343 server_base.cc:1061] running on GCE node
I20260812 06:16:24.353951  4343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:24.354076  4343 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:24.354096  4343 hybrid_clock.cc:648] HybridClock initialized: now 1786515384354096 us; error 0 us; skew 500 ppm
I20260812 06:16:24.355310  4343 webserver.cc:533] Webserver started at http://127.4.61.193:45493/ using document root <none> and password file <none>
I20260812 06:16:24.355511  4343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:24.355581  4343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:24.355696  4343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:24.356125  4343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/instance:
uuid: "1840f073b5814d00b49fea3b1393eb63"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-3h5h"
I20260812 06:16:24.357884  4343 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:24.359174  4492 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:24.359546  4343 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:24.359614  4343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root
uuid: "1840f073b5814d00b49fea3b1393eb63"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-3h5h"
I20260812 06:16:24.359712  4343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-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:24.367359  4343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:24.367902  4343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:24.368443  4343 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:24.369465  4343 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:24.369520  4343 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:24.369606  4343 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:24.369645  4343 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:24.377385  4343 rpc_server.cc:307] RPC server started. Bound to: 127.4.61.193:46249
I20260812 06:16:24.377420  4592 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.61.193:46249 every 8 connection(s)
I20260812 06:16:24.394050  4594 heartbeater.cc:344] Connected to a master server at 127.4.61.254:38945
I20260812 06:16:24.394362  4594 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:24.394901  4594 heartbeater.cc:507] Master 127.4.61.254:38945 requested a full tablet report, sending...
I20260812 06:16:24.396611  4388 ts_manager.cc:194] Registered new tserver with Master: 1840f073b5814d00b49fea3b1393eb63 (127.4.61.193:46249)
I20260812 06:16:24.397321  4343 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.019192002s
I20260812 06:16:24.398270  4388 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54322
I20260812 06:16:24.407846  4388 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54332:
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:24.422930  4539 tablet_service.cc:1511] Processing CreateTablet for tablet 10fb46c4ba694ea7804acb30499c142e (DEFAULT_TABLE table=heavy-update-compaction-test [id=937340e46c314eb0978e2188faff2f2c]), partition=
I20260812 06:16:24.423561  4539 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 10fb46c4ba694ea7804acb30499c142e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:24.426435  4612 tablet_bootstrap.cc:492] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Bootstrap starting.
I20260812 06:16:24.427461  4612 tablet_bootstrap.cc:654] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:24.428721  4612 tablet_bootstrap.cc:492] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: No bootstrap required, opened a new log
I20260812 06:16:24.428813  4612 ts_tablet_manager.cc:1403] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:24.429813  4612 raft_consensus.cc:359] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1840f073b5814d00b49fea3b1393eb63" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 46249 } }
I20260812 06:16:24.429961  4612 raft_consensus.cc:385] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:24.430006  4612 raft_consensus.cc:740] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1840f073b5814d00b49fea3b1393eb63, State: Initialized, Role: FOLLOWER
I20260812 06:16:24.430172  4612 consensus_queue.cc:260] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [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: "1840f073b5814d00b49fea3b1393eb63" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 46249 } }
I20260812 06:16:24.430275  4612 raft_consensus.cc:399] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:24.430334  4612 raft_consensus.cc:493] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:24.430395  4612 raft_consensus.cc:3060] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:24.431226  4612 raft_consensus.cc:515] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1840f073b5814d00b49fea3b1393eb63" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 46249 } }
I20260812 06:16:24.431396  4612 leader_election.cc:304] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [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: 1840f073b5814d00b49fea3b1393eb63; no voters: 
I20260812 06:16:24.431684  4612 leader_election.cc:290] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:24.431803  4617 raft_consensus.cc:2804] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:24.432021  4617 raft_consensus.cc:697] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 1 LEADER]: Becoming Leader. State: Replica: 1840f073b5814d00b49fea3b1393eb63, State: Running, Role: LEADER
I20260812 06:16:24.432114  4612 ts_tablet_manager.cc:1434] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:24.432183  4617 consensus_queue.cc:237] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [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: "1840f073b5814d00b49fea3b1393eb63" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 46249 } }
I20260812 06:16:24.432454  4594 heartbeater.cc:499] Master 127.4.61.254:38945 was elected leader, sending a full tablet report...
I20260812 06:16:24.435258  4385 catalog_manager.cc:5719] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1840f073b5814d00b49fea3b1393eb63 (127.4.61.193). New cstate: current_term: 1 leader_uuid: "1840f073b5814d00b49fea3b1393eb63" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1840f073b5814d00b49fea3b1393eb63" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 46249 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:24.503145  4343 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.020s	sys 0.008s
I20260812 06:16:24.628890  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushMRSOp(10fb46c4ba694ea7804acb30499c142e): perf score=15.086190
I20260812 06:16:24.792250  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushMRSOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.163s	user 0.115s	sys 0.032s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":241,"delete_count":0,"dirs.queue_time_us":123,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1041,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46200,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":118,"threads_started":1,"update_count":1450}
I20260812 06:16:24.793416  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling LogGCOp(10fb46c4ba694ea7804acb30499c142e): free 20743880 bytes of WAL
I20260812 06:16:24.793766  4499 log_reader.cc:385] T 10fb46c4ba694ea7804acb30499c142e: removed 2 log segments from log reader
I20260812 06:16:24.793852  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000001 (ops 1-6)
I20260812 06:16:24.793924  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000002 (ops 7-11)
I20260812 06:16:24.798195  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: LogGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:24.798601  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e): 12719218 bytes on disk
I20260812 06:16:24.799419  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:16:24.799927  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:24.817023  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.017s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5887,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.817518  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:24.954734  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.137s	user 0.117s	sys 0.016s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":476,"lbm_read_time_us":7320,"lbm_reads_lt_1ms":454,"lbm_write_time_us":28419,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":260,"threads_started":5,"update_count":1950}
I20260812 06:16:24.955309  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=10.126437
I20260812 06:16:25.003583  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18729,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.004052  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:25.016476  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.017166  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:25.156108  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.139s	user 0.102s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":9925,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29600,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:16:25.156840  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=10.126437
I20260812 06:16:25.214056  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.057s	user 0.019s	sys 0.037s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":27712,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":299,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.214670  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:25.233608  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.019s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.234138  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:25.402233  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.168s	user 0.101s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":9904,"lbm_reads_lt_1ms":468,"lbm_write_time_us":32024,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.402698  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:25.463363  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.061s	user 0.018s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29661,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.463905  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:25.478374  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.479146  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:25.677592  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.198s	user 0.125s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":13090,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33059,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:25.678421  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:25.809338  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.131s	user 0.075s	sys 0.055s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":62548,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.810380  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:25.839243  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.028s	user 0.018s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.840271  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:26.173589  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.333s	user 0.231s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2528,"lbm_read_time_us":24651,"lbm_reads_lt_1ms":572,"lbm_write_time_us":71217,"lbm_writes_lt_1ms":543,"mutex_wait_us":676,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:16:26.174786  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:26.304714  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.129s	user 0.078s	sys 0.044s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":67432,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.306412  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:26.358188  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.051s	user 0.023s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":13469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.359445  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:26.386814  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.027s	user 0.009s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.387874  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:26.716962  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.329s	user 0.263s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1136,"lbm_read_time_us":22958,"lbm_reads_lt_1ms":673,"lbm_write_time_us":78051,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":48256,"thread_start_us":628,"threads_started":5,"update_count":3000}
I20260812 06:16:26.718241  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:26.860781  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.142s	user 0.056s	sys 0.056s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":53563,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.862042  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=6.157687
I20260812 06:16:26.916754  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.054s	user 0.018s	sys 0.033s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":18084,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:26.918205  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushMRSOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:27.037312  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushMRSOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.119s	user 0.072s	sys 0.008s Metrics: {"bytes_written":1398556,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":345,"dirs.run_wall_time_us":2064,"drs_written":1,"lbm_read_time_us":181,"lbm_reads_lt_1ms":4,"lbm_write_time_us":5334,"lbm_writes_lt_1ms":44,"mutex_wait_us":2601,"peak_mem_usage":0,"rows_written":34}
I20260812 06:16:27.039733  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e): 518 bytes on disk
I20260812 06:16:27.041061  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":208,"lbm_reads_lt_1ms":4}
I20260812 06:16:27.042354  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=3.181125
I20260812 06:16:27.087894  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.045s	user 0.019s	sys 0.018s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":17090,"lbm_writes_lt_1ms":113,"mutex_wait_us":4,"reinsert_count":0,"update_count":550}
I20260812 06:16:27.089051  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling LogGCOp(10fb46c4ba694ea7804acb30499c142e): free 141338430 bytes of WAL
I20260812 06:16:27.089645  4499 log_reader.cc:385] T 10fb46c4ba694ea7804acb30499c142e: removed 14 log segments from log reader
I20260812 06:16:27.089792  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000003 (ops 12-16)
I20260812 06:16:27.089959  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000004 (ops 17-21)
I20260812 06:16:27.090101  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000005 (ops 22-26)
I20260812 06:16:27.090194  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000006 (ops 27-31)
I20260812 06:16:27.090273  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000007 (ops 32-36)
I20260812 06:16:27.090325  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000008 (ops 37-41)
I20260812 06:16:27.090389  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000009 (ops 42-46)
I20260812 06:16:27.090423  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000010 (ops 47-51)
I20260812 06:16:27.090480  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000011 (ops 52-56)
I20260812 06:16:27.090528  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000012 (ops 57-60)
I20260812 06:16:27.090587  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000013 (ops 61-65)
I20260812 06:16:27.090621  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000014 (ops 66-70)
I20260812 06:16:27.090734  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000015 (ops 71-74)
I20260812 06:16:27.090839  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000016 (ops 75-79)
I20260812 06:16:27.150866  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: LogGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.061s	user 0.004s	sys 0.055s Metrics: {}
I20260812 06:16:27.151876  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:27.185606  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.033s	user 0.020s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":11741,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:27.186372  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:27.558674  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.372s	user 0.243s	sys 0.128s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":579,"lbm_read_time_us":32565,"lbm_reads_lt_1ms":866,"lbm_write_time_us":67361,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"thread_start_us":426,"threads_started":7,"update_count":4000}
I20260812 06:16:27.559962  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=18.063937
I20260812 06:16:27.631537  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.071s	user 0.041s	sys 0.027s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":31610,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:27.632324  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:27.654359  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.022s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.655061  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:27.844910  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.190s	user 0.144s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1110,"lbm_read_time_us":12514,"lbm_reads_lt_1ms":664,"lbm_write_time_us":39964,"lbm_writes_lt_1ms":643,"mutex_wait_us":257,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3000}
I20260812 06:16:27.845561  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=15.087375
I20260812 06:16:27.895767  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.050s	user 0.018s	sys 0.022s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":18880,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:27.896365  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:27.917889  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.021s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.918465  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:27.929792  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:27.930647  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:28.110934  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.180s	user 0.130s	sys 0.049s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":487,"lbm_read_time_us":12869,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40128,"lbm_writes_lt_1ms":643,"mutex_wait_us":149,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":83200,"update_count":3000}
I20260812 06:16:28.111625  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:28.170225  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.058s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24675,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.170754  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:28.182494  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.183066  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:28.336428  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.153s	user 0.116s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":902,"lbm_read_time_us":11113,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33003,"lbm_writes_lt_1ms":543,"mutex_wait_us":389,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26496,"update_count":2500}
I20260812 06:16:28.337256  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=12.110812
I20260812 06:16:28.377262  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.040s	user 0.026s	sys 0.013s Metrics: {"bytes_written":13702312,"delete_count":0,"lbm_write_time_us":17648,"lbm_writes_lt_1ms":337,"reinsert_count":0,"update_count":1670}
I20260812 06:16:28.377820  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.196750
I20260812 06:16:28.399628  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.022s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:16:28.400115  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:28.410094  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3765,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:28.410552  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:28.582749  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.172s	user 0.095s	sys 0.075s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":740,"lbm_read_time_us":12245,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33771,"lbm_writes_lt_1ms":543,"mutex_wait_us":409,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:16:28.583559  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=11.118625
I20260812 06:16:28.632331  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.048s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19626,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:28.633081  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:28.659071  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.025s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":6021,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:16:28.659653  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:28.674836  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5791,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:16:28.675504  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushMRSOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:28.713780  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushMRSOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.038s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152513,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1696,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2154,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:28.714490  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling LogGCOp(10fb46c4ba694ea7804acb30499c142e): free 112239343 bytes of WAL
I20260812 06:16:28.714728  4499 log_reader.cc:385] T 10fb46c4ba694ea7804acb30499c142e: removed 11 log segments from log reader
I20260812 06:16:28.714771  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000017 (ops 80-84)
I20260812 06:16:28.714802  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000018 (ops 85-89)
I20260812 06:16:28.714866  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000019 (ops 90-94)
I20260812 06:16:28.714908  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000020 (ops 95-99)
I20260812 06:16:28.714949  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000021 (ops 100-104)
I20260812 06:16:28.714990  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000022 (ops 105-108)
I20260812 06:16:28.715030  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000023 (ops 109-113)
I20260812 06:16:28.715070  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000024 (ops 114-118)
I20260812 06:16:28.715109  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000025 (ops 119-123)
I20260812 06:16:28.715149  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000026 (ops 124-128)
I20260812 06:16:28.715196  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000027 (ops 129-133)
I20260812 06:16:28.739332  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: LogGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:28.739766  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=3.181125
I20260812 06:16:28.764801  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.025s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":6289,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:28.765360  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e): 447 bytes on disk
I20260812 06:16:28.765782  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:28.766278  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:28.776113  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3590,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:28.776644  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:28.988034  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.211s	user 0.156s	sys 0.048s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":586,"lbm_read_time_us":15256,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37444,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:16:28.989354  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=15.087375
I20260812 06:16:29.049961  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.060s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21675,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:29.050537  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=6.157687
I20260812 06:16:29.076133  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.025s	user 0.011s	sys 0.012s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":11118,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:29.076630  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:29.246755  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.170s	user 0.139s	sys 0.030s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":12552,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34442,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:29.247495  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:29.311473  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.064s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":28940,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.312199  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:29.339179  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.027s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.339668  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:29.352104  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.353156  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:29.548623  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.195s	user 0.138s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1331,"lbm_read_time_us":13607,"lbm_reads_lt_1ms":673,"lbm_write_time_us":43773,"lbm_writes_lt_1ms":643,"mutex_wait_us":318,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":3000}
I20260812 06:16:29.549537  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:29.614730  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.065s	user 0.038s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30853,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.615309  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:29.629276  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.014s	user 0.001s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.629920  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:29.782919  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.153s	user 0.120s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":612,"lbm_read_time_us":10027,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29462,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:29.783869  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:29.846418  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.062s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22084,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.846995  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:29.857996  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.858700  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:30.028815  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.170s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":11234,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29233,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:30.029417  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=14.095187
I20260812 06:16:30.087749  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.058s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20529,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.088406  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:30.103049  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.103616  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushMRSOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:30.135473  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushMRSOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1815,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:30.136250  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling LogGCOp(10fb46c4ba694ea7804acb30499c142e): free 120553592 bytes of WAL
I20260812 06:16:30.136551  4499 log_reader.cc:385] T 10fb46c4ba694ea7804acb30499c142e: removed 12 log segments from log reader
I20260812 06:16:30.136620  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000028 (ops 134-138)
I20260812 06:16:30.136668  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000029 (ops 139-142)
I20260812 06:16:30.136706  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000030 (ops 143-147)
I20260812 06:16:30.136732  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000031 (ops 148-152)
I20260812 06:16:30.136761  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000032 (ops 153-157)
I20260812 06:16:30.136794  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000033 (ops 158-162)
I20260812 06:16:30.136873  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000034 (ops 163-167)
I20260812 06:16:30.136916  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000035 (ops 168-172)
I20260812 06:16:30.136941  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000036 (ops 173-177)
I20260812 06:16:30.136966  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000037 (ops 178-182)
I20260812 06:16:30.137012  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000038 (ops 183-186)
I20260812 06:16:30.137053  4499 log.cc:1079] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/10fb46c4ba694ea7804acb30499c142e/wal-000000039 (ops 187-191)
I20260812 06:16:30.171545  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: LogGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.035s	user 0.002s	sys 0.030s Metrics: {}
I20260812 06:16:30.172286  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e): 462 bytes on disk
I20260812 06:16:30.172788  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: UndoDeltaBlockGCOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.173439  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:30.200742  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.027s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.201448  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=2.188937
I20260812 06:16:30.213147  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.213960  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:30.356118  4343 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.853s	user 2.162s	sys 0.128s
I20260812 06:16:30.428128  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.214s	user 0.128s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16365,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39505,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:16:30.428669  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e): perf score=10.126437
I20260812 06:16:30.453724  4343 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.097s	user 0.003s	sys 0.000s
I20260812 06:16:30.454386  4343 tablet_server.cc:179] TabletServer@127.4.61.193:0 shutting down...
I20260812 06:16:30.460544  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: FlushDeltaMemStoresOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.032s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13789,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.461359  4596 maintenance_manager.cc:419] P 1840f073b5814d00b49fea3b1393eb63: Scheduling MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e): perf score=1.000000
I20260812 06:16:30.554728  4499 maintenance_manager.cc:643] P 1840f073b5814d00b49fea3b1393eb63: MajorDeltaCompactionOp(10fb46c4ba694ea7804acb30499c142e) complete. Timing: real 0.093s	user 0.072s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":548,"lbm_read_time_us":7163,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18445,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":20,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":1500}
I20260812 06:16:30.555644  4343 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:30.556110  4343 tablet_replica.cc:333] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63: stopping tablet replica
I20260812 06:16:30.556445  4343 raft_consensus.cc:2243] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:30.556754  4343 raft_consensus.cc:2272] T 10fb46c4ba694ea7804acb30499c142e P 1840f073b5814d00b49fea3b1393eb63 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:30.573583  4343 tablet_server.cc:196] TabletServer@127.4.61.193:0 shutdown complete.
I20260812 06:16:30.589623  4343 master.cc:562] Master@127.4.61.254:38945 shutting down...
I20260812 06:16:30.593760  4343 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:30.593935  4343 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:30.594000  4343 tablet_replica.cc:333] T 00000000000000000000000000000000 P 113980f842a74d2798fdbd459ec7a308: stopping tablet replica
I20260812 06:16:30.606735  4343 master.cc:584] Master@127.4.61.254:38945 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6508 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:30.703692  4343 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.61.254:34487
I20260812 06:16:30.704077  4343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:30.706840  4666 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:30.706987  4343 server_base.cc:1061] running on GCE node
W20260812 06:16:30.707018  4663 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:30.707121  4670 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:30.707382  4343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:30.707450  4343 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:30.707518  4343 hybrid_clock.cc:648] HybridClock initialized: now 1786515390707517 us; error 0 us; skew 500 ppm
I20260812 06:16:30.708565  4343 webserver.cc:533] Webserver started at http://127.4.61.254:44869/ using document root <none> and password file <none>
I20260812 06:16:30.708778  4343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:30.708928  4343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:30.709059  4343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:30.709533  4343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/master-0-root/instance:
uuid: "ed0186e3b3f24d4f9ab849b07e17a805"
format_stamp: "Formatted at 2026-08-12 06:16:30 on dist-test-slave-3h5h"
I20260812 06:16:30.711367  4343 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:30.712520  4675 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:30.712875  4343 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:30.712975  4343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/master-0-root
uuid: "ed0186e3b3f24d4f9ab849b07e17a805"
format_stamp: "Formatted at 2026-08-12 06:16:30 on dist-test-slave-3h5h"
I20260812 06:16:30.713068  4343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-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:30.722281  4343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:30.722669  4343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:30.727025  4343 rpc_server.cc:307] RPC server started. Bound to: 127.4.61.254:34487
I20260812 06:16:30.729918  4764 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:30.731415  4763 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.61.254:34487 every 8 connection(s)
I20260812 06:16:30.742430  4764 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805: Bootstrap starting.
I20260812 06:16:30.743919  4764 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:30.745483  4764 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805: No bootstrap required, opened a new log
I20260812 06:16:30.746130  4764 raft_consensus.cc:359] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed0186e3b3f24d4f9ab849b07e17a805" member_type: VOTER }
I20260812 06:16:30.746277  4764 raft_consensus.cc:385] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:30.746336  4764 raft_consensus.cc:740] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ed0186e3b3f24d4f9ab849b07e17a805, State: Initialized, Role: FOLLOWER
I20260812 06:16:30.746517  4764 consensus_queue.cc:260] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [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: "ed0186e3b3f24d4f9ab849b07e17a805" member_type: VOTER }
I20260812 06:16:30.746604  4764 raft_consensus.cc:399] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:30.746665  4764 raft_consensus.cc:493] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:30.746730  4764 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:30.747599  4764 raft_consensus.cc:515] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed0186e3b3f24d4f9ab849b07e17a805" member_type: VOTER }
I20260812 06:16:30.747764  4764 leader_election.cc:304] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [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: ed0186e3b3f24d4f9ab849b07e17a805; no voters: 
I20260812 06:16:30.748013  4764 leader_election.cc:290] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:30.748174  4770 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:30.748389  4770 raft_consensus.cc:697] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 1 LEADER]: Becoming Leader. State: Replica: ed0186e3b3f24d4f9ab849b07e17a805, State: Running, Role: LEADER
I20260812 06:16:30.748541  4770 consensus_queue.cc:237] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [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: "ed0186e3b3f24d4f9ab849b07e17a805" member_type: VOTER }
I20260812 06:16:30.748554  4764 sys_catalog.cc:565] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:30.749037  4774 sys_catalog.cc:455] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ed0186e3b3f24d4f9ab849b07e17a805. Latest consensus state: current_term: 1 leader_uuid: "ed0186e3b3f24d4f9ab849b07e17a805" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed0186e3b3f24d4f9ab849b07e17a805" member_type: VOTER } }
I20260812 06:16:30.749224  4774 sys_catalog.cc:458] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:30.749025  4771 sys_catalog.cc:455] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ed0186e3b3f24d4f9ab849b07e17a805" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ed0186e3b3f24d4f9ab849b07e17a805" member_type: VOTER } }
I20260812 06:16:30.749454  4771 sys_catalog.cc:458] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:30.749522  4776 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:30.750382  4776 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:30.750950  4343 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:30.752259  4776 catalog_manager.cc:1383] Generated new cluster ID: 79a37b5f12cb4194bafefea077c396e6
I20260812 06:16:30.752345  4776 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:30.775372  4776 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:30.776042  4776 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:30.781141  4776 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805: Generated new TSK 0
I20260812 06:16:30.781343  4776 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:30.783350  4343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:30.785573  4799 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:30.785683  4343 server_base.cc:1061] running on GCE node
W20260812 06:16:30.785737  4801 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:30.785713  4798 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:30.786026  4343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:30.786074  4343 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:30.786089  4343 hybrid_clock.cc:648] HybridClock initialized: now 1786515390786090 us; error 0 us; skew 500 ppm
I20260812 06:16:30.786981  4343 webserver.cc:533] Webserver started at http://127.4.61.193:46089/ using document root <none> and password file <none>
I20260812 06:16:30.787180  4343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:30.787231  4343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:30.787343  4343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:30.787760  4343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/instance:
uuid: "550cd98360044fe8998a2808534e350d"
format_stamp: "Formatted at 2026-08-12 06:16:30 on dist-test-slave-3h5h"
I20260812 06:16:30.789381  4343 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:30.790426  4809 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:30.790709  4343 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:30.790799  4343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root
uuid: "550cd98360044fe8998a2808534e350d"
format_stamp: "Formatted at 2026-08-12 06:16:30 on dist-test-slave-3h5h"
I20260812 06:16:30.790890  4343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-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:30.803678  4343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:30.804091  4343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:30.804440  4343 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:30.805013  4343 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:30.805073  4343 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:30.805130  4343 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:30.805181  4343 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:30.809790  4343 rpc_server.cc:307] RPC server started. Bound to: 127.4.61.193:35401
I20260812 06:16:30.809818  4913 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.61.193:35401 every 8 connection(s)
I20260812 06:16:30.819895  4915 heartbeater.cc:344] Connected to a master server at 127.4.61.254:34487
I20260812 06:16:30.820209  4915 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:30.820533  4915 heartbeater.cc:507] Master 127.4.61.254:34487 requested a full tablet report, sending...
I20260812 06:16:30.821349  4705 ts_manager.cc:194] Registered new tserver with Master: 550cd98360044fe8998a2808534e350d (127.4.61.193:35401)
I20260812 06:16:30.821561  4343 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011294327s
I20260812 06:16:30.822289  4705 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:32874
I20260812 06:16:30.829424  4705 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:32882:
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:30.839125  4857 tablet_service.cc:1511] Processing CreateTablet for tablet 3a3bc5077223428caee96bc8cb204329 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7d00bb54c3954075ae50d0f8b3052608]), partition=
I20260812 06:16:30.839406  4857 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3a3bc5077223428caee96bc8cb204329. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:30.841614  4932 tablet_bootstrap.cc:492] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Bootstrap starting.
I20260812 06:16:30.842500  4932 tablet_bootstrap.cc:654] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:30.843648  4932 tablet_bootstrap.cc:492] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: No bootstrap required, opened a new log
I20260812 06:16:30.843725  4932 ts_tablet_manager.cc:1403] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:30.844188  4932 raft_consensus.cc:359] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "550cd98360044fe8998a2808534e350d" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 35401 } }
I20260812 06:16:30.844322  4932 raft_consensus.cc:385] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:30.844360  4932 raft_consensus.cc:740] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 550cd98360044fe8998a2808534e350d, State: Initialized, Role: FOLLOWER
I20260812 06:16:30.844493  4932 consensus_queue.cc:260] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [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: "550cd98360044fe8998a2808534e350d" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 35401 } }
I20260812 06:16:30.844609  4932 raft_consensus.cc:399] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:30.844652  4932 raft_consensus.cc:493] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:30.844710  4932 raft_consensus.cc:3060] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:30.845511  4932 raft_consensus.cc:515] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "550cd98360044fe8998a2808534e350d" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 35401 } }
I20260812 06:16:30.845654  4932 leader_election.cc:304] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [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: 550cd98360044fe8998a2808534e350d; no voters: 
I20260812 06:16:30.845808  4932 leader_election.cc:290] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:30.846113  4937 raft_consensus.cc:2804] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:30.846113  4932 ts_tablet_manager.cc:1434] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:30.846172  4915 heartbeater.cc:499] Master 127.4.61.254:34487 was elected leader, sending a full tablet report...
I20260812 06:16:30.846271  4937 raft_consensus.cc:697] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 1 LEADER]: Becoming Leader. State: Replica: 550cd98360044fe8998a2808534e350d, State: Running, Role: LEADER
I20260812 06:16:30.846446  4937 consensus_queue.cc:237] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [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: "550cd98360044fe8998a2808534e350d" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 35401 } }
I20260812 06:16:30.847868  4705 catalog_manager.cc:5719] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d reported cstate change: term changed from 0 to 1, leader changed from <none> to 550cd98360044fe8998a2808534e350d (127.4.61.193). New cstate: current_term: 1 leader_uuid: "550cd98360044fe8998a2808534e350d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "550cd98360044fe8998a2808534e350d" member_type: VOTER last_known_addr { host: "127.4.61.193" port: 35401 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:30.909557  4343 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.016s	sys 0.007s
I20260812 06:16:31.060742  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushMRSOp(3a3bc5077223428caee96bc8cb204329): perf score=19.054940
I20260812 06:16:31.213496  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushMRSOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.152s	user 0.111s	sys 0.041s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":180,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":988,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39595,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:31.214255  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling LogGCOp(3a3bc5077223428caee96bc8cb204329): free 20743880 bytes of WAL
I20260812 06:16:31.214509  4816 log_reader.cc:385] T 3a3bc5077223428caee96bc8cb204329: removed 2 log segments from log reader
I20260812 06:16:31.214576  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000001 (ops 1-6)
I20260812 06:16:31.214630  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000002 (ops 7-11)
I20260812 06:16:31.219099  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: LogGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:31.219683  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:31.237728  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.018s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.238287  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:31.379305  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.141s	user 0.097s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":968,"lbm_read_time_us":9054,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25500,"lbm_writes_lt_1ms":443,"mutex_wait_us":105,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"thread_start_us":334,"threads_started":5,"update_count":2000}
I20260812 06:16:31.379948  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:31.438308  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.058s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.438892  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329): 16411392 bytes on disk
I20260812 06:16:31.439376  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:16:31.439810  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:31.451238  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.451695  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:31.612972  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.161s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1095,"lbm_read_time_us":12044,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28323,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:16:31.613502  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=11.118625
I20260812 06:16:31.648175  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.034s	user 0.010s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15365,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:31.648860  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:31.664443  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.665239  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:31.821043  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.156s	user 0.102s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":10367,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23451,"lbm_writes_lt_1ms":443,"mutex_wait_us":238,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:16:31.821708  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=11.118625
I20260812 06:16:31.854863  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.033s	user 0.022s	sys 0.009s Metrics: {"bytes_written":13086955,"delete_count":0,"lbm_write_time_us":14183,"lbm_writes_lt_1ms":322,"reinsert_count":0,"update_count":1595}
I20260812 06:16:31.855347  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:31.877700  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.022s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3742,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:16:31.878248  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:31.898216  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.020s	user 0.003s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.898768  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:32.099423  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.200s	user 0.118s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":233,"lbm_read_time_us":12246,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32393,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:16:32.100229  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:32.152633  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.052s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20467,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.153203  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:32.164620  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.165174  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:32.339627  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.174s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":149,"lbm_read_time_us":10476,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28057,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:16:32.340343  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:32.385325  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.045s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20332,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.385900  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:32.402132  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.016s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.402738  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushMRSOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:32.430630  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushMRSOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":145,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1589,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1414,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:32.431344  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling LogGCOp(3a3bc5077223428caee96bc8cb204329): free 111786266 bytes of WAL
I20260812 06:16:32.431656  4816 log_reader.cc:385] T 3a3bc5077223428caee96bc8cb204329: removed 11 log segments from log reader
I20260812 06:16:32.431735  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000003 (ops 12-16)
I20260812 06:16:32.431785  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000004 (ops 17-20)
I20260812 06:16:32.431846  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000005 (ops 21-25)
I20260812 06:16:32.431890  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000006 (ops 26-30)
I20260812 06:16:32.431942  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000007 (ops 31-35)
I20260812 06:16:32.431980  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000008 (ops 36-40)
I20260812 06:16:32.432027  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000009 (ops 41-45)
I20260812 06:16:32.432068  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000010 (ops 46-50)
I20260812 06:16:32.432107  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000011 (ops 51-55)
I20260812 06:16:32.432147  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000012 (ops 56-60)
I20260812 06:16:32.432184  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000013 (ops 61-64)
I20260812 06:16:32.457363  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: LogGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:32.457944  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329): 446 bytes on disk
I20260812 06:16:32.458451  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.458930  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=3.181125
I20260812 06:16:32.486589  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.027s	user 0.006s	sys 0.014s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7588,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:32.487155  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:32.498791  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:32.499336  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:32.749191  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.250s	user 0.155s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":972,"lbm_read_time_us":17813,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38743,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":742,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21120,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:16:32.749867  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=18.063937
I20260812 06:16:32.814463  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.064s	user 0.032s	sys 0.029s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27876,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:32.814942  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:32.825944  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.826717  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:33.038375  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.211s	user 0.144s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":15419,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33275,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:16:33.039160  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:33.100351  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.061s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23265,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:33.100922  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:33.113268  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.113965  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:33.309754  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.196s	user 0.136s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":409,"lbm_read_time_us":13939,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32174,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:16:33.310312  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:33.373729  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.063s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24136,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.374307  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:33.386942  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.388355  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:33.573468  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.185s	user 0.106s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":11148,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34415,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:16:33.574190  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:33.635800  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.061s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:33.636559  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:33.648677  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.649397  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:33.833848  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.184s	user 0.132s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":622,"lbm_read_time_us":13321,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30711,"lbm_writes_lt_1ms":543,"mutex_wait_us":285,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:16:33.834417  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:33.885027  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.050s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20495,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.885553  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:33.906543  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.021s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.907181  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushMRSOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:33.943090  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushMRSOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.036s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1598,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2221,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:33.943782  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling LogGCOp(3a3bc5077223428caee96bc8cb204329): free 120553382 bytes of WAL
I20260812 06:16:33.944020  4816 log_reader.cc:385] T 3a3bc5077223428caee96bc8cb204329: removed 12 log segments from log reader
I20260812 06:16:33.944067  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000014 (ops 65-69)
I20260812 06:16:33.944095  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000015 (ops 70-74)
I20260812 06:16:33.944156  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000016 (ops 75-79)
I20260812 06:16:33.944201  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000017 (ops 80-84)
I20260812 06:16:33.944243  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000018 (ops 85-89)
I20260812 06:16:33.944283  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000019 (ops 90-94)
I20260812 06:16:33.944324  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000020 (ops 95-98)
I20260812 06:16:33.944365  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000021 (ops 99-103)
I20260812 06:16:33.944402  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000022 (ops 104-108)
I20260812 06:16:33.944443  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000023 (ops 109-112)
I20260812 06:16:33.944486  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000024 (ops 113-117)
I20260812 06:16:33.944528  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000025 (ops 118-122)
I20260812 06:16:33.968971  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: LogGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:33.969511  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:33.994971  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.025s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.995537  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329): 447 bytes on disk
I20260812 06:16:33.996091  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.996639  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:34.007121  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.007575  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:34.274071  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.266s	user 0.158s	sys 0.095s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1472,"lbm_read_time_us":15318,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44249,"lbm_writes_lt_1ms":743,"mutex_wait_us":373,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19456,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:16:34.274729  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=18.063937
I20260812 06:16:34.354799  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.080s	user 0.049s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31982,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.355365  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:34.366225  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.366957  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:34.602195  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.235s	user 0.133s	sys 0.092s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":904,"lbm_read_time_us":14710,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37671,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":3000}
I20260812 06:16:34.602864  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=18.063937
I20260812 06:16:34.672976  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.070s	user 0.036s	sys 0.020s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":25249,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.673487  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:34.685895  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.686590  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:34.905508  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.219s	user 0.127s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":12172,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36464,"lbm_writes_lt_1ms":643,"mutex_wait_us":72,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":47360,"update_count":3000}
I20260812 06:16:34.906240  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=18.063937
I20260812 06:16:34.977968  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.072s	user 0.041s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27996,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.978519  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:34.992101  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.992901  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:35.197325  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.204s	user 0.128s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":972,"lbm_read_time_us":16708,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31920,"lbm_writes_lt_1ms":643,"mutex_wait_us":346,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3000}
I20260812 06:16:35.197849  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=15.087375
I20260812 06:16:35.249783  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.052s	user 0.038s	sys 0.013s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":22674,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:35.250468  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:35.266659  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.016s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5453,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.267171  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:35.440514  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.173s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774679,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":11547,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29097,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:16:35.442107  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=14.095187
I20260812 06:16:35.501695  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.059s	user 0.044s	sys 0.014s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22898,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:35.502245  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:35.513006  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.513451  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushMRSOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:35.552719  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushMRSOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.039s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1454,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1548,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:35.553524  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling LogGCOp(3a3bc5077223428caee96bc8cb204329): free 121459726 bytes of WAL
I20260812 06:16:35.553795  4816 log_reader.cc:385] T 3a3bc5077223428caee96bc8cb204329: removed 12 log segments from log reader
I20260812 06:16:35.553864  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000026 (ops 123-127)
I20260812 06:16:35.553917  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000027 (ops 128-132)
I20260812 06:16:35.553953  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000028 (ops 133-137)
I20260812 06:16:35.553992  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000029 (ops 138-142)
I20260812 06:16:35.554028  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000030 (ops 143-147)
I20260812 06:16:35.554064  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000031 (ops 148-152)
I20260812 06:16:35.554100  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000032 (ops 153-157)
I20260812 06:16:35.554137  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000033 (ops 158-162)
I20260812 06:16:35.554174  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000034 (ops 163-167)
I20260812 06:16:35.554210  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000035 (ops 168-172)
I20260812 06:16:35.554248  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000036 (ops 173-177)
I20260812 06:16:35.554284  4816 log.cc:1079] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: Deleting log segment in path: /tmp/dist-test-taskJq05nz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384179216-4343-0/minicluster-data/ts-0-root/wals/3a3bc5077223428caee96bc8cb204329/wal-000000037 (ops 178-182)
I20260812 06:16:35.579103  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: LogGCOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:16:35.579519  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:35.594172  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.594591  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329): 472 bytes on disk
I20260812 06:16:35.594980  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: UndoDeltaBlockGCOp(3a3bc5077223428caee96bc8cb204329) 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:35.595449  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:35.606534  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.011s	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:35.607322  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:35.837374  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.230s	user 0.126s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979747,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":695,"lbm_read_time_us":15466,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39689,"lbm_writes_lt_1ms":743,"mutex_wait_us":48,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:16:35.838135  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=18.063937
I20260812 06:16:35.901412  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.063s	user 0.043s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28613,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:35.901966  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329): perf score=2.188937
I20260812 06:16:35.914232  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: FlushDeltaMemStoresOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.914678  4916 maintenance_manager.cc:419] P 550cd98360044fe8998a2808534e350d: Scheduling MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329): perf score=1.000000
I20260812 06:16:35.982025  4343 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.072s	user 1.876s	sys 0.182s
I20260812 06:16:36.045233  4343 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.003s	sys 0.000s
I20260812 06:16:36.045755  4343 tablet_server.cc:179] TabletServer@127.4.61.193:0 shutting down...
I20260812 06:16:36.073948  4816 maintenance_manager.cc:643] P 550cd98360044fe8998a2808534e350d: MajorDeltaCompactionOp(3a3bc5077223428caee96bc8cb204329) complete. Timing: real 0.159s	user 0.144s	sys 0.015s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1199,"lbm_read_time_us":11592,"lbm_reads_lt_1ms":668,"lbm_write_time_us":30595,"lbm_writes_lt_1ms":643,"mutex_wait_us":152,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:16:36.074818  4343 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:36.075368  4343 tablet_replica.cc:333] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d: stopping tablet replica
I20260812 06:16:36.075519  4343 raft_consensus.cc:2243] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:36.075722  4343 raft_consensus.cc:2272] T 3a3bc5077223428caee96bc8cb204329 P 550cd98360044fe8998a2808534e350d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:36.080937  4343 tablet_server.cc:196] TabletServer@127.4.61.193:0 shutdown complete.
I20260812 06:16:36.126914  4343 master.cc:562] Master@127.4.61.254:34487 shutting down...
I20260812 06:16:36.130698  4343 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:36.130927  4343 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:36.131019  4343 tablet_replica.cc:333] T 00000000000000000000000000000000 P ed0186e3b3f24d4f9ab849b07e17a805: stopping tablet replica
I20260812 06:16:36.143751  4343 master.cc:584] Master@127.4.61.254:34487 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5536 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12045 ms total)

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