[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:20.993382  9658 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.110.190:37381
I20260812 06:19:20.994310  9658 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:20.994886  9658 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.000806  9668 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.000881  9658 server_base.cc:1061] running on GCE node
W20260812 06:19:21.000835  9665 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:21.001083  9666 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.001567  9658 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.001657  9658 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:21.001696  9658 hybrid_clock.cc:648] HybridClock initialized: now 1786515561001694 us; error 0 us; skew 500 ppm
I20260812 06:19:21.003310  9658 webserver.cc:533] Webserver started at http://127.9.110.190:46353/ using document root <none> and password file <none>
I20260812 06:19:21.003784  9658 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.003835  9658 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.004014  9658 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.005568  9658 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/master-0-root/instance:
uuid: "a13ec49af7264e7185e951fbfd139af8"
format_stamp: "Formatted at 2026-08-12 06:19:20 on dist-test-slave-266d"
I20260812 06:19:21.008708  9658 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:21.010596  9677 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.011518  9658 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:21.011620  9658 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/master-0-root
uuid: "a13ec49af7264e7185e951fbfd139af8"
format_stamp: "Formatted at 2026-08-12 06:19:20 on dist-test-slave-266d"
I20260812 06:19:21.011698  9658 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:21.034711  9658 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.035333  9658 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:21.035490  9658 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.042634  9658 rpc_server.cc:307] RPC server started. Bound to: 127.9.110.190:37381
I20260812 06:19:21.042635  9778 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.110.190:37381 every 8 connection(s)
I20260812 06:19:21.044745  9780 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:21.049877  9780 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8: Bootstrap starting.
I20260812 06:19:21.052105  9780 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.052924  9780 log.cc:826] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:21.054528  9780 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8: No bootstrap required, opened a new log
I20260812 06:19:21.057126  9780 raft_consensus.cc:359] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a13ec49af7264e7185e951fbfd139af8" member_type: VOTER }
I20260812 06:19:21.057288  9780 raft_consensus.cc:385] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.057358  9780 raft_consensus.cc:740] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a13ec49af7264e7185e951fbfd139af8, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.057893  9780 consensus_queue.cc:260] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [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: "a13ec49af7264e7185e951fbfd139af8" member_type: VOTER }
I20260812 06:19:21.058043  9780 raft_consensus.cc:399] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.058107  9780 raft_consensus.cc:493] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.058220  9780 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.058921  9780 raft_consensus.cc:515] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a13ec49af7264e7185e951fbfd139af8" member_type: VOTER }
I20260812 06:19:21.059324  9780 leader_election.cc:304] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [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: a13ec49af7264e7185e951fbfd139af8; no voters: 
I20260812 06:19:21.059603  9780 leader_election.cc:290] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.059690  9789 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.059892  9789 raft_consensus.cc:697] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 1 LEADER]: Becoming Leader. State: Replica: a13ec49af7264e7185e951fbfd139af8, State: Running, Role: LEADER
I20260812 06:19:21.060284  9789 consensus_queue.cc:237] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [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: "a13ec49af7264e7185e951fbfd139af8" member_type: VOTER }
I20260812 06:19:21.060495  9780 sys_catalog.cc:565] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:21.062058  9794 sys_catalog.cc:455] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a13ec49af7264e7185e951fbfd139af8. Latest consensus state: current_term: 1 leader_uuid: "a13ec49af7264e7185e951fbfd139af8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a13ec49af7264e7185e951fbfd139af8" member_type: VOTER } }
I20260812 06:19:21.062090  9790 sys_catalog.cc:455] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a13ec49af7264e7185e951fbfd139af8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a13ec49af7264e7185e951fbfd139af8" member_type: VOTER } }
I20260812 06:19:21.062206  9794 sys_catalog.cc:458] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.062206  9790 sys_catalog.cc:458] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.062510  9811 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:21.062687  9658 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:21.064517  9811 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:21.068446  9811 catalog_manager.cc:1383] Generated new cluster ID: 7d3f1afbb0214806bca13b73a1d30e72
I20260812 06:19:21.068502  9811 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:21.100409  9811 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:21.101305  9811 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:21.111907  9811 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8: Generated new TSK 0
I20260812 06:19:21.112485  9811 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:21.127736  9658 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.130566  9828 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:21.130625  9827 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:21.130738  9833 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.130980  9658 server_base.cc:1061] running on GCE node
I20260812 06:19:21.131142  9658 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.131188  9658 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:21.131209  9658 hybrid_clock.cc:648] HybridClock initialized: now 1786515561131209 us; error 0 us; skew 500 ppm
I20260812 06:19:21.132061  9658 webserver.cc:533] Webserver started at http://127.9.110.129:42925/ using document root <none> and password file <none>
I20260812 06:19:21.132220  9658 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.132270  9658 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.132345  9658 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.132695  9658 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/instance:
uuid: "fd2042f2803547e7bfcdb318c1a3a44f"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-266d"
I20260812 06:19:21.134137  9658 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:21.135010  9839 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.135215  9658 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:21.135282  9658 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root
uuid: "fd2042f2803547e7bfcdb318c1a3a44f"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-266d"
I20260812 06:19:21.135345  9658 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:21.186046  9658 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.186614  9658 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.187094  9658 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:21.188002  9658 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:21.188058  9658 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.188099  9658 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:21.188115  9658 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.194165  9658 rpc_server.cc:307] RPC server started. Bound to: 127.9.110.129:44345
I20260812 06:19:21.194205  9948 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.110.129:44345 every 8 connection(s)
I20260812 06:19:21.206324  9949 heartbeater.cc:344] Connected to a master server at 127.9.110.190:37381
I20260812 06:19:21.206589  9949 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:21.207098  9949 heartbeater.cc:507] Master 127.9.110.190:37381 requested a full tablet report, sending...
I20260812 06:19:21.208570  9713 ts_manager.cc:194] Registered new tserver with Master: fd2042f2803547e7bfcdb318c1a3a44f (127.9.110.129:44345)
I20260812 06:19:21.209267  9658 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014507587s
I20260812 06:19:21.210081  9713 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38196
I20260812 06:19:21.217931  9713 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38198:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:21.230155  9886 tablet_service.cc:1511] Processing CreateTablet for tablet e40ef915f8be4486929bcf6b58ba6e4d (DEFAULT_TABLE table=heavy-update-compaction-test [id=ea6517a109fb4667a4bc521b5d921df2]), partition=
I20260812 06:19:21.230533  9886 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e40ef915f8be4486929bcf6b58ba6e4d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:21.232658  9976 tablet_bootstrap.cc:492] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Bootstrap starting.
I20260812 06:19:21.233425  9976 tablet_bootstrap.cc:654] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.234323  9976 tablet_bootstrap.cc:492] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: No bootstrap required, opened a new log
I20260812 06:19:21.234422  9976 ts_tablet_manager.cc:1403] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:21.234876  9976 raft_consensus.cc:359] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd2042f2803547e7bfcdb318c1a3a44f" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 44345 } }
I20260812 06:19:21.234988  9976 raft_consensus.cc:385] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.235020  9976 raft_consensus.cc:740] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fd2042f2803547e7bfcdb318c1a3a44f, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.235121  9976 consensus_queue.cc:260] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [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: "fd2042f2803547e7bfcdb318c1a3a44f" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 44345 } }
I20260812 06:19:21.235177  9976 raft_consensus.cc:399] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.235206  9976 raft_consensus.cc:493] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.235239  9976 raft_consensus.cc:3060] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.235934  9976 raft_consensus.cc:515] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd2042f2803547e7bfcdb318c1a3a44f" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 44345 } }
I20260812 06:19:21.236049  9976 leader_election.cc:304] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [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: fd2042f2803547e7bfcdb318c1a3a44f; no voters: 
I20260812 06:19:21.236192  9976 leader_election.cc:290] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.236342  9983 raft_consensus.cc:2804] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.236519  9976 ts_tablet_manager.cc:1434] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:21.236549  9983 raft_consensus.cc:697] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 1 LEADER]: Becoming Leader. State: Replica: fd2042f2803547e7bfcdb318c1a3a44f, State: Running, Role: LEADER
I20260812 06:19:21.236775  9949 heartbeater.cc:499] Master 127.9.110.190:37381 was elected leader, sending a full tablet report...
I20260812 06:19:21.236899  9983 consensus_queue.cc:237] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [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: "fd2042f2803547e7bfcdb318c1a3a44f" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 44345 } }
I20260812 06:19:21.239323  9711 catalog_manager.cc:5719] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f reported cstate change: term changed from 0 to 1, leader changed from <none> to fd2042f2803547e7bfcdb318c1a3a44f (127.9.110.129). New cstate: current_term: 1 leader_uuid: "fd2042f2803547e7bfcdb318c1a3a44f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd2042f2803547e7bfcdb318c1a3a44f" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 44345 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:21.293265  9658 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.019s	sys 0.004s
I20260812 06:19:21.445261  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=23.023690
I20260812 06:19:21.624756  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.179s	user 0.140s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":210,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1036,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42421,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":128,"threads_started":1,"update_count":1500}
I20260812 06:19:21.625945  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d): free 20743880 bytes of WAL
I20260812 06:19:21.626246  9848 log_reader.cc:385] T e40ef915f8be4486929bcf6b58ba6e4d: removed 2 log segments from log reader
I20260812 06:19:21.626313  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000001 (ops 1-6)
I20260812 06:19:21.626359  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000002 (ops 7-11)
I20260812 06:19:21.631366  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:21.631668  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:21.643958  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.644403  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d): 20513813 bytes on disk
I20260812 06:19:21.645012  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d) 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:19:21.645421  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:21.776857  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.131s	user 0.099s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":539,"lbm_read_time_us":9471,"lbm_reads_lt_1ms":460,"lbm_write_time_us":19837,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":263,"threads_started":5,"update_count":2000}
I20260812 06:19:21.777338  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=10.126437
I20260812 06:19:21.813870  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13504,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.814320  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:21.824110  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.824543  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:21.949250  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.124s	user 0.106s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":502,"lbm_read_time_us":9099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23196,"lbm_writes_lt_1ms":443,"mutex_wait_us":337,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:21.949854  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=10.126437
I20260812 06:19:21.987054  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.037s	user 0.028s	sys 0.002s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13586,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.987519  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.002249  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.002743  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:22.121941  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.119s	user 0.098s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":7994,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23398,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.122409  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=10.126437
I20260812 06:19:22.175252  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.053s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15764,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.175819  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.185659  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.186025  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:22.325217  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.139s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":879,"lbm_read_time_us":9822,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21040,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.325858  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=10.126437
I20260812 06:19:22.367286  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.041s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13190,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.367784  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.379345  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.379817  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:22.509146  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.129s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1115,"lbm_read_time_us":8991,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24291,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23296,"update_count":2000}
I20260812 06:19:22.509840  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=11.118625
I20260812 06:19:22.551426  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.041s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15682,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:22.551892  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.571046  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.571494  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.579963  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3146,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:22.580333  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:22.720620  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.140s	user 0.124s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1033,"lbm_read_time_us":10135,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27298,"lbm_writes_lt_1ms":543,"mutex_wait_us":266,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:22.722841  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=10.126437
I20260812 06:19:22.756431  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.033s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.756911  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.771462  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.772188  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:22.799710  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1367,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1368,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:22.800482  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d): free 121006429 bytes of WAL
I20260812 06:19:22.800760  9848 log_reader.cc:385] T e40ef915f8be4486929bcf6b58ba6e4d: removed 12 log segments from log reader
I20260812 06:19:22.800837  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000003 (ops 12-16)
I20260812 06:19:22.800879  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000004 (ops 17-21)
I20260812 06:19:22.800913  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000005 (ops 22-26)
I20260812 06:19:22.800941  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000006 (ops 27-31)
I20260812 06:19:22.800971  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000007 (ops 32-36)
I20260812 06:19:22.801000  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000008 (ops 37-41)
I20260812 06:19:22.801033  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000009 (ops 42-46)
I20260812 06:19:22.801062  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000010 (ops 47-51)
I20260812 06:19:22.801113  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000011 (ops 52-56)
I20260812 06:19:22.801144  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000012 (ops 57-60)
I20260812 06:19:22.801173  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000013 (ops 61-65)
I20260812 06:19:22.801206  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000014 (ops 66-70)
I20260812 06:19:22.826406  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:22.826964  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=3.181125
I20260812 06:19:22.838162  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:22.838541  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d): 463 bytes on disk
I20260812 06:19:22.838912  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.839331  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:22.848181  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3213,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:22.848552  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:23.001376  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.153s	user 0.124s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2722,"lbm_read_time_us":10835,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29380,"lbm_writes_lt_1ms":643,"mutex_wait_us":1114,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:19:23.001808  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:23.042836  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.041s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17338,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.043304  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:23.058534  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.059038  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:23.209481  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.150s	user 0.107s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":8835,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27837,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:19:23.210093  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:23.257625  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.047s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21315,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.258198  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:23.402259  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.144s	user 0.101s	sys 0.042s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":143,"lbm_read_time_us":9477,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25526,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:19:23.402774  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:23.445326  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.042s	user 0.023s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18105,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.445735  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:23.455469  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.455988  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:23.639565  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.183s	user 0.122s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":12255,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30604,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":263,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:23.640100  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:23.689360  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.049s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18730,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.689924  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:23.700791  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.701282  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:23.868441  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.167s	user 0.104s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":10427,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30278,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:19:23.869021  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:23.917008  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.048s	user 0.019s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17351,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.917531  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:23.927940  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.928524  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:24.069950  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.141s	user 0.129s	sys 0.012s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":537,"lbm_read_time_us":9156,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28817,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34048,"update_count":2500}
I20260812 06:19:24.070533  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=11.118625
I20260812 06:19:24.105021  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.034s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":14187,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:24.105623  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:24.130499  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.025s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4870,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":450}
I20260812 06:19:24.130995  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:24.141043  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.141539  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:24.170879  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1237,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1561,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:24.171589  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d): free 132118272 bytes of WAL
I20260812 06:19:24.171818  9848 log_reader.cc:385] T e40ef915f8be4486929bcf6b58ba6e4d: removed 13 log segments from log reader
I20260812 06:19:24.171872  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000015 (ops 71-75)
I20260812 06:19:24.171918  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000016 (ops 76-80)
I20260812 06:19:24.171949  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000017 (ops 81-84)
I20260812 06:19:24.171972  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000018 (ops 85-89)
I20260812 06:19:24.171998  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000019 (ops 90-94)
I20260812 06:19:24.172026  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000020 (ops 95-99)
I20260812 06:19:24.172058  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000021 (ops 100-104)
I20260812 06:19:24.172096  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000022 (ops 105-108)
I20260812 06:19:24.172120  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000023 (ops 109-113)
I20260812 06:19:24.172149  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000024 (ops 114-118)
I20260812 06:19:24.172183  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000025 (ops 119-122)
I20260812 06:19:24.172214  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000026 (ops 123-127)
I20260812 06:19:24.172238  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000027 (ops 128-132)
I20260812 06:19:24.199249  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:24.199687  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=3.181125
I20260812 06:19:24.213279  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:24.213730  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d): 482 bytes on disk
I20260812 06:19:24.214128  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.214594  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:24.224001  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3410,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.224421  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:24.449426  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.225s	user 0.155s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020847,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1346,"lbm_read_time_us":15262,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35725,"lbm_writes_lt_1ms":743,"mutex_wait_us":661,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:19:24.450387  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=15.087375
I20260812 06:19:24.514811  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.064s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":25517,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:19:24.515362  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=6.157687
I20260812 06:19:24.534382  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.019s	user 0.016s	sys 0.002s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":7253,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:24.534848  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:24.721191  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.186s	user 0.122s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":914,"lbm_read_time_us":13548,"lbm_reads_lt_1ms":664,"lbm_write_time_us":30180,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:24.721745  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:24.775362  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.053s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17290,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.775841  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:24.791325  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.791870  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:24.962147  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.170s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":584,"lbm_read_time_us":11793,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27887,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:24.962602  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:25.014093  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.051s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17159,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.014644  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:25.025409  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.025872  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:25.189953  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.164s	user 0.120s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":11345,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27724,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:19:25.190511  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=14.095187
I20260812 06:19:25.252702  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.062s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21335,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.253221  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:25.263402  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.263788  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:25.426065  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.162s	user 0.102s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":551,"lbm_read_time_us":11186,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27503,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:19:25.426610  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=11.118625
I20260812 06:19:25.463716  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.037s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15570,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:25.464231  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:25.493574  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.029s	user 0.003s	sys 0.018s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.494117  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:25.507550  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4905,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.507977  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:25.550115  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushMRSOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.042s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1304,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1637,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":768}
I20260812 06:19:25.550837  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d): free 112239554 bytes of WAL
I20260812 06:19:25.551061  9848 log_reader.cc:385] T e40ef915f8be4486929bcf6b58ba6e4d: removed 11 log segments from log reader
I20260812 06:19:25.551123  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000028 (ops 133-137)
I20260812 06:19:25.551165  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000029 (ops 138-142)
I20260812 06:19:25.551195  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000030 (ops 143-146)
I20260812 06:19:25.551218  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000031 (ops 147-151)
I20260812 06:19:25.551249  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000032 (ops 152-156)
I20260812 06:19:25.551290  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000033 (ops 157-161)
I20260812 06:19:25.551319  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000034 (ops 162-166)
I20260812 06:19:25.551347  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000035 (ops 167-171)
I20260812 06:19:25.551375  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000036 (ops 172-176)
I20260812 06:19:25.551409  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000037 (ops 177-181)
I20260812 06:19:25.551440  9848 log.cc:1079] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/e40ef915f8be4486929bcf6b58ba6e4d/wal-000000038 (ops 182-186)
I20260812 06:19:25.573139  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: LogGCOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.022s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:25.573519  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:25.593699  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.020s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.594142  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=2.188937
I20260812 06:19:25.608217  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.014s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.608719  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:25.814129  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.205s	user 0.145s	sys 0.059s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":448,"lbm_read_time_us":14023,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33299,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":65920,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:25.814682  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=16.079562
I20260812 06:19:25.828214  9658 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.535s	user 1.676s	sys 0.116s
I20260812 06:19:25.866562  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.051s	user 0.033s	sys 0.017s Metrics: {"bytes_written":17886768,"delete_count":0,"lbm_write_time_us":23623,"lbm_writes_lt_1ms":439,"reinsert_count":0,"update_count":2180}
I20260812 06:19:25.867167  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d): 447 bytes on disk
I20260812 06:19:25.867578  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: UndoDeltaBlockGCOp(e40ef915f8be4486929bcf6b58ba6e4d) 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:19:25.868145  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.196750
I20260812 06:19:25.875706  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: FlushDeltaMemStoresOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":2645,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:19:25.876080  9951 maintenance_manager.cc:419] P fd2042f2803547e7bfcdb318c1a3a44f: Scheduling MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d): perf score=1.000000
I20260812 06:19:25.887576  9658 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.059s	user 0.002s	sys 0.000s
I20260812 06:19:25.888254  9658 tablet_server.cc:179] TabletServer@127.9.110.129:0 shutting down...
I20260812 06:19:26.008358  9848 maintenance_manager.cc:643] P fd2042f2803547e7bfcdb318c1a3a44f: MajorDeltaCompactionOp(e40ef915f8be4486929bcf6b58ba6e4d) complete. Timing: real 0.132s	user 0.078s	sys 0.052s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512260,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":529,"dirs.run_cpu_time_us":432,"dirs.run_wall_time_us":2373,"lbm_read_time_us":8140,"lbm_reads_lt_1ms":518,"lbm_write_time_us":21343,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:26.008971  9658 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:26.009366  9658 tablet_replica.cc:333] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f: stopping tablet replica
I20260812 06:19:26.009596  9658 raft_consensus.cc:2243] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:26.009845  9658 raft_consensus.cc:2272] T e40ef915f8be4486929bcf6b58ba6e4d P fd2042f2803547e7bfcdb318c1a3a44f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:26.024428  9658 tablet_server.cc:196] TabletServer@127.9.110.129:0 shutdown complete.
I20260812 06:19:26.050913  9658 master.cc:562] Master@127.9.110.190:37381 shutting down...
I20260812 06:19:26.054358  9658 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:26.054509  9658 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:26.054561  9658 tablet_replica.cc:333] T 00000000000000000000000000000000 P a13ec49af7264e7185e951fbfd139af8: stopping tablet replica
I20260812 06:19:26.066524  9658 master.cc:584] Master@127.9.110.190:37381 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5305 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:26.298475  9658 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.110.190:33309
I20260812 06:19:26.298823  9658 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:26.300628 10010 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:26.300700  9658 server_base.cc:1061] running on GCE node
W20260812 06:19:26.300750 10009 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:26.300630 10012 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:26.301003  9658 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:26.301045  9658 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:26.301059  9658 hybrid_clock.cc:648] HybridClock initialized: now 1786515566301059 us; error 0 us; skew 500 ppm
I20260812 06:19:26.301820  9658 webserver.cc:533] Webserver started at http://127.9.110.190:38141/ using document root <none> and password file <none>
I20260812 06:19:26.301949  9658 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:26.301986  9658 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:26.302040  9658 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:26.302347  9658 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/master-0-root/instance:
uuid: "89cf7217107c4ada95fa8ab46ac1ac84"
format_stamp: "Formatted at 2026-08-12 06:19:26 on dist-test-slave-266d"
I20260812 06:19:26.303665  9658 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:26.304481 10019 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:26.304683  9658 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:26.304752  9658 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/master-0-root
uuid: "89cf7217107c4ada95fa8ab46ac1ac84"
format_stamp: "Formatted at 2026-08-12 06:19:26 on dist-test-slave-266d"
I20260812 06:19:26.304826  9658 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:26.318293  9658 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:26.318575  9658 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:26.322329  9658 rpc_server.cc:307] RPC server started. Bound to: 127.9.110.190:33309
I20260812 06:19:26.334800 10104 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.110.190:33309 every 8 connection(s)
I20260812 06:19:26.335216 10105 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:26.336918 10105 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84: Bootstrap starting.
I20260812 06:19:26.337677 10105 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:26.338558 10105 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84: No bootstrap required, opened a new log
I20260812 06:19:26.338932 10105 raft_consensus.cc:359] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89cf7217107c4ada95fa8ab46ac1ac84" member_type: VOTER }
I20260812 06:19:26.339015 10105 raft_consensus.cc:385] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:26.339046 10105 raft_consensus.cc:740] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 89cf7217107c4ada95fa8ab46ac1ac84, State: Initialized, Role: FOLLOWER
I20260812 06:19:26.339182 10105 consensus_queue.cc:260] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [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: "89cf7217107c4ada95fa8ab46ac1ac84" member_type: VOTER }
I20260812 06:19:26.339268 10105 raft_consensus.cc:399] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:26.339308 10105 raft_consensus.cc:493] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:26.339356 10105 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:26.340004 10105 raft_consensus.cc:515] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89cf7217107c4ada95fa8ab46ac1ac84" member_type: VOTER }
I20260812 06:19:26.340130 10105 leader_election.cc:304] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [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: 89cf7217107c4ada95fa8ab46ac1ac84; no voters: 
I20260812 06:19:26.340302 10105 leader_election.cc:290] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:26.340385 10108 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:26.340569 10108 raft_consensus.cc:697] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 1 LEADER]: Becoming Leader. State: Replica: 89cf7217107c4ada95fa8ab46ac1ac84, State: Running, Role: LEADER
I20260812 06:19:26.340713 10105 sys_catalog.cc:565] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:26.340704 10108 consensus_queue.cc:237] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [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: "89cf7217107c4ada95fa8ab46ac1ac84" member_type: VOTER }
I20260812 06:19:26.341168 10111 sys_catalog.cc:455] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 89cf7217107c4ada95fa8ab46ac1ac84. Latest consensus state: current_term: 1 leader_uuid: "89cf7217107c4ada95fa8ab46ac1ac84" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89cf7217107c4ada95fa8ab46ac1ac84" member_type: VOTER } }
I20260812 06:19:26.341288 10111 sys_catalog.cc:458] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:26.341151 10110 sys_catalog.cc:455] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "89cf7217107c4ada95fa8ab46ac1ac84" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89cf7217107c4ada95fa8ab46ac1ac84" member_type: VOTER } }
I20260812 06:19:26.341408 10110 sys_catalog.cc:458] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:26.341835 10115 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:26.342535 10115 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:26.342684  9658 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:26.344198 10115 catalog_manager.cc:1383] Generated new cluster ID: 236674de73b54a26acbbd40ce2dfdc36
I20260812 06:19:26.344255 10115 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:26.348666 10115 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:26.349224 10115 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:26.358624 10115 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84: Generated new TSK 0
I20260812 06:19:26.358767 10115 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:26.374785  9658 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:26.376474 10138 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:26.376560 10142 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:26.376613  9658 server_base.cc:1061] running on GCE node
W20260812 06:19:26.376535 10145 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:26.376827  9658 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:26.376873  9658 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:26.376888  9658 hybrid_clock.cc:648] HybridClock initialized: now 1786515566376888 us; error 0 us; skew 500 ppm
I20260812 06:19:26.377660  9658 webserver.cc:533] Webserver started at http://127.9.110.129:41101/ using document root <none> and password file <none>
I20260812 06:19:26.377803  9658 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:26.377858  9658 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:26.377931  9658 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:26.378284  9658 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/instance:
uuid: "410778b55f1c4d5fa7f4902685d965cc"
format_stamp: "Formatted at 2026-08-12 06:19:26 on dist-test-slave-266d"
I20260812 06:19:26.379652  9658 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:26.380484 10151 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:26.380699  9658 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:26.380767  9658 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root
uuid: "410778b55f1c4d5fa7f4902685d965cc"
format_stamp: "Formatted at 2026-08-12 06:19:26 on dist-test-slave-266d"
I20260812 06:19:26.380837  9658 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:26.399946  9658 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:26.400266  9658 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:26.400539  9658 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:26.400962  9658 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:26.401000  9658 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:26.401041  9658 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:26.401069  9658 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:26.404863  9658 rpc_server.cc:307] RPC server started. Bound to: 127.9.110.129:37005
I20260812 06:19:26.404932 10270 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.110.129:37005 every 8 connection(s)
I20260812 06:19:26.412846 10272 heartbeater.cc:344] Connected to a master server at 127.9.110.190:33309
I20260812 06:19:26.412940 10272 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:26.413180 10272 heartbeater.cc:507] Master 127.9.110.190:33309 requested a full tablet report, sending...
I20260812 06:19:26.413784 10044 ts_manager.cc:194] Registered new tserver with Master: 410778b55f1c4d5fa7f4902685d965cc (127.9.110.129:37005)
I20260812 06:19:26.414052  9658 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008740199s
I20260812 06:19:26.414721 10044 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37384
I20260812 06:19:26.420166 10044 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37388:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:26.427870 10200 tablet_service.cc:1511] Processing CreateTablet for tablet 196e2964022b4afe862b9bcf22d5c845 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c680b28b6f474301958cd250d3ca54ec]), partition=
I20260812 06:19:26.428108 10200 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 196e2964022b4afe862b9bcf22d5c845. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:26.429953 10290 tablet_bootstrap.cc:492] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Bootstrap starting.
I20260812 06:19:26.430738 10290 tablet_bootstrap.cc:654] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:26.431684 10290 tablet_bootstrap.cc:492] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: No bootstrap required, opened a new log
I20260812 06:19:26.431756 10290 ts_tablet_manager.cc:1403] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:26.432133 10290 raft_consensus.cc:359] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410778b55f1c4d5fa7f4902685d965cc" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 37005 } }
I20260812 06:19:26.432214 10290 raft_consensus.cc:385] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:26.432248 10290 raft_consensus.cc:740] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 410778b55f1c4d5fa7f4902685d965cc, State: Initialized, Role: FOLLOWER
I20260812 06:19:26.432375 10290 consensus_queue.cc:260] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [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: "410778b55f1c4d5fa7f4902685d965cc" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 37005 } }
I20260812 06:19:26.432456 10290 raft_consensus.cc:399] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:26.432495 10290 raft_consensus.cc:493] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:26.432543 10290 raft_consensus.cc:3060] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:26.433279 10290 raft_consensus.cc:515] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410778b55f1c4d5fa7f4902685d965cc" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 37005 } }
I20260812 06:19:26.433398 10290 leader_election.cc:304] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [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: 410778b55f1c4d5fa7f4902685d965cc; no voters: 
I20260812 06:19:26.433585 10290 leader_election.cc:290] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:26.433686 10292 raft_consensus.cc:2804] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:26.433895 10272 heartbeater.cc:499] Master 127.9.110.190:33309 was elected leader, sending a full tablet report...
I20260812 06:19:26.433947 10292 raft_consensus.cc:697] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 1 LEADER]: Becoming Leader. State: Replica: 410778b55f1c4d5fa7f4902685d965cc, State: Running, Role: LEADER
I20260812 06:19:26.433893 10290 ts_tablet_manager.cc:1434] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:26.434089 10292 consensus_queue.cc:237] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [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: "410778b55f1c4d5fa7f4902685d965cc" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 37005 } }
I20260812 06:19:26.435252 10044 catalog_manager.cc:5719] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc reported cstate change: term changed from 0 to 1, leader changed from <none> to 410778b55f1c4d5fa7f4902685d965cc (127.9.110.129). New cstate: current_term: 1 leader_uuid: "410778b55f1c4d5fa7f4902685d965cc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410778b55f1c4d5fa7f4902685d965cc" member_type: VOTER last_known_addr { host: "127.9.110.129" port: 37005 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:26.486994  9658 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.013s	sys 0.008s
I20260812 06:19:26.655789 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushMRSOp(196e2964022b4afe862b9bcf22d5c845): perf score=23.023690
I20260812 06:19:26.798049 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushMRSOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.142s	user 0.096s	sys 0.044s Metrics: {"bytes_written":13825383,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":838,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38017,"lbm_writes_lt_1ms":894,"mutex_wait_us":762,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1536,"update_count":1685}
I20260812 06:19:26.798696 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.196750
I20260812 06:19:26.816773 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.018s	user 0.002s	sys 0.008s Metrics: {"bytes_written":2994984,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:19:26.817209 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling LogGCOp(196e2964022b4afe862b9bcf22d5c845): free 20743880 bytes of WAL
I20260812 06:19:26.817431 10159 log_reader.cc:385] T 196e2964022b4afe862b9bcf22d5c845: removed 2 log segments from log reader
I20260812 06:19:26.817488 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000001 (ops 1-6)
I20260812 06:19:26.817528 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000002 (ops 7-11)
I20260812 06:19:26.820850 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: LogGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:26.821158 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845): 20513809 bytes on disk
I20260812 06:19:26.821489 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:26.821846 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:26.837484 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.015s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3134,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:26.837939 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:27.015523 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.177s	user 0.115s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815767,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":394,"lbm_read_time_us":13343,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26435,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":243,"threads_started":5,"update_count":2500}
I20260812 06:19:27.015933 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:27.061501 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.045s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":17770,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.061946 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:27.071185 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.071609 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:27.237639 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.166s	user 0.109s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":10173,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24407,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38656,"update_count":2500}
I20260812 06:19:27.238137 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:27.285487 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.047s	user 0.033s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.285993 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:27.300439 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.300884 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:27.454432 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.153s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":143,"lbm_read_time_us":9144,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27918,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38400,"update_count":2500}
I20260812 06:19:27.454994 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:27.504451 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.049s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19805,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.504971 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:27.514658 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.515208 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:27.660218 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.145s	user 0.109s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":537,"lbm_read_time_us":9278,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26385,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:27.660725 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:27.702105 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.041s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17895,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.702570 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:27.717657 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.718161 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:27.873447 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.155s	user 0.127s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1098,"lbm_read_time_us":9108,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27208,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:19:27.873950 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:27.919982 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.046s	user 0.021s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18079,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:27.920452 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:27.934998 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.935590 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushMRSOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:27.962386 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushMRSOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.027s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":168,"dirs.run_wall_time_us":1213,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1393,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:27.962956 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling LogGCOp(196e2964022b4afe862b9bcf22d5c845): free 124257240 bytes of WAL
I20260812 06:19:27.963263 10159 log_reader.cc:385] T 196e2964022b4afe862b9bcf22d5c845: removed 12 log segments from log reader
I20260812 06:19:27.963377 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000003 (ops 12-16)
I20260812 06:19:27.963434 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000004 (ops 17-21)
I20260812 06:19:27.963459 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000005 (ops 22-26)
I20260812 06:19:27.963513 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000006 (ops 27-31)
I20260812 06:19:27.963567 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000007 (ops 32-36)
I20260812 06:19:27.963601 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000008 (ops 37-41)
I20260812 06:19:27.963627 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000009 (ops 42-46)
I20260812 06:19:27.963683 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000010 (ops 47-50)
I20260812 06:19:27.963716 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000011 (ops 51-55)
I20260812 06:19:27.963737 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000012 (ops 56-60)
I20260812 06:19:27.963759 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000013 (ops 61-65)
I20260812 06:19:27.963792 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000014 (ops 66-70)
I20260812 06:19:27.988874 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: LogGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:27.989319 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=3.181125
I20260812 06:19:28.000795 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3832,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:28.001194 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845): 472 bytes on disk
I20260812 06:19:28.001542 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:19:28.001956 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:28.010633 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3148,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:28.010973 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:28.193621 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.183s	user 0.141s	sys 0.040s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":995,"lbm_read_time_us":12247,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36735,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:19:28.194151 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:28.238848 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19495,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.239279 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:28.260726 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.021s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.261201 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:28.271075 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.271502 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:28.423944 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.152s	user 0.117s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918212,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1082,"lbm_read_time_us":11070,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31661,"lbm_writes_lt_1ms":643,"mutex_wait_us":300,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":3000}
I20260812 06:19:28.424430 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:28.471187 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.047s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20255,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.471668 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:28.487177 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.487613 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:28.639556 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.152s	user 0.106s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":8456,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28520,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:28.640045 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:28.677949 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.038s	user 0.025s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16677,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.678460 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:28.819044 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.140s	user 0.094s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":60,"lbm_read_time_us":10326,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23044,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:19:28.820096 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=10.126437
I20260812 06:19:28.855276 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.035s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15067,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.855712 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:28.867208 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.867614 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:28.991952 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.124s	user 0.103s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":597,"lbm_read_time_us":9479,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22198,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:28.992553 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=10.126437
I20260812 06:19:29.031613 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.039s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.032164 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:29.047644 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.048115 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:29.168011 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.120s	user 0.096s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":8981,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20645,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.168532 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=10.126437
I20260812 06:19:29.208953 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.040s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14269,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.209508 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:29.219852 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.220431 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushMRSOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:29.250489 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushMRSOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1201,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1246,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:29.251194 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling LogGCOp(196e2964022b4afe862b9bcf22d5c845): free 121006436 bytes of WAL
I20260812 06:19:29.251437 10159 log_reader.cc:385] T 196e2964022b4afe862b9bcf22d5c845: removed 12 log segments from log reader
I20260812 06:19:29.251489 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000015 (ops 71-75)
I20260812 06:19:29.251533 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000016 (ops 76-80)
I20260812 06:19:29.251564 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000017 (ops 81-85)
I20260812 06:19:29.251590 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000018 (ops 86-90)
I20260812 06:19:29.251621 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000019 (ops 91-95)
I20260812 06:19:29.251649 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000020 (ops 96-100)
I20260812 06:19:29.251677 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000021 (ops 101-104)
I20260812 06:19:29.251706 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000022 (ops 105-109)
I20260812 06:19:29.251739 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000023 (ops 110-114)
I20260812 06:19:29.251770 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000024 (ops 115-119)
I20260812 06:19:29.251798 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000025 (ops 120-124)
I20260812 06:19:29.251827 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000026 (ops 125-129)
I20260812 06:19:29.276081 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: LogGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:29.276531 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845): 462 bytes on disk
I20260812 06:19:29.276916 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845) 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:19:29.277417 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=3.181125
I20260812 06:19:29.290238 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:29.290640 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:29.299393 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3268,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.299741 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:29.451911 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.152s	user 0.110s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":148,"lbm_read_time_us":10939,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28951,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:19:29.452474 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:29.499513 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.047s	user 0.036s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19395,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.500015 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:29.510049 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.510596 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:29.657379 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.147s	user 0.086s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":9343,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26054,"lbm_writes_lt_1ms":543,"mutex_wait_us":328,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:19:29.657963 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:29.715323 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.057s	user 0.013s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18993,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.715886 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:29.731258 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.731771 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:29.886010 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.154s	user 0.104s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":10237,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26122,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:29.886670 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:29.934980 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.048s	user 0.024s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18030,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.935508 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:29.950659 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5917,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.952824 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:30.120119 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":928,"lbm_read_time_us":12393,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27879,"lbm_writes_lt_1ms":543,"mutex_wait_us":229,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:30.120661 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:30.185446 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.065s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20360,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.185945 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:30.195773 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.196193 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:30.375870 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.180s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":12513,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29416,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:30.376382 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:30.419166 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.043s	user 0.036s	sys 0.000s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15977,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.419682 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:30.439193 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.019s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.439811 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:30.610459 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.170s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":10791,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26917,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:30.611013 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=14.095187
I20260812 06:19:30.659938 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.049s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19312,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.660470 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:30.674435 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5368,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.674939 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushMRSOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:30.710373 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushMRSOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1240,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2133,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:30.711175 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling LogGCOp(196e2964022b4afe862b9bcf22d5c845): free 133024646 bytes of WAL
I20260812 06:19:30.711410 10159 log_reader.cc:385] T 196e2964022b4afe862b9bcf22d5c845: removed 13 log segments from log reader
I20260812 06:19:30.711457 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000027 (ops 130-134)
I20260812 06:19:30.711495 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000028 (ops 135-138)
I20260812 06:19:30.711529 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000029 (ops 139-143)
I20260812 06:19:30.711560 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000030 (ops 144-148)
I20260812 06:19:30.711591 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000031 (ops 149-153)
I20260812 06:19:30.711621 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000032 (ops 154-158)
I20260812 06:19:30.711653 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000033 (ops 159-163)
I20260812 06:19:30.711685 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000034 (ops 164-168)
I20260812 06:19:30.711716 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000035 (ops 169-173)
I20260812 06:19:30.711747 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000036 (ops 174-178)
I20260812 06:19:30.711786 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000037 (ops 179-183)
I20260812 06:19:30.711817 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000038 (ops 184-188)
I20260812 06:19:30.711848 10159 log.cc:1079] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: Deleting log segment in path: /tmp/dist-test-taskKbtK7Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515560983136-9658-0/minicluster-data/ts-0-root/wals/196e2964022b4afe862b9bcf22d5c845/wal-000000039 (ops 189-193)
I20260812 06:19:30.735070 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: LogGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:30.735479 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=3.181125
I20260812 06:19:30.752816 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:30.753297 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845): 492 bytes on disk
I20260812 06:19:30.753682 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: UndoDeltaBlockGCOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:30.754249 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845): perf score=2.188937
I20260812 06:19:30.763101 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: FlushDeltaMemStoresOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3234,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:30.763499 10273 maintenance_manager.cc:419] P 410778b55f1c4d5fa7f4902685d965cc: Scheduling MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845): perf score=1.000000
I20260812 06:19:30.847431  9658 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.360s	user 1.628s	sys 0.134s
I20260812 06:19:30.936565  9658 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.001s	sys 0.000s
I20260812 06:19:30.937036  9658 tablet_server.cc:179] TabletServer@127.9.110.129:0 shutting down...
I20260812 06:19:30.959227 10159 maintenance_manager.cc:643] P 410778b55f1c4d5fa7f4902685d965cc: MajorDeltaCompactionOp(196e2964022b4afe862b9bcf22d5c845) complete. Timing: real 0.196s	user 0.139s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020731,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1233,"lbm_read_time_us":13556,"lbm_reads_lt_1ms":770,"lbm_write_time_us":30022,"lbm_writes_lt_1ms":743,"mutex_wait_us":284,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:19:30.959774  9658 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:30.960085  9658 tablet_replica.cc:333] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc: stopping tablet replica
I20260812 06:19:30.960206  9658 raft_consensus.cc:2243] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:30.960371  9658 raft_consensus.cc:2272] T 196e2964022b4afe862b9bcf22d5c845 P 410778b55f1c4d5fa7f4902685d965cc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:30.974696  9658 tablet_server.cc:196] TabletServer@127.9.110.129:0 shutdown complete.
I20260812 06:19:31.015142  9658 master.cc:562] Master@127.9.110.190:33309 shutting down...
I20260812 06:19:31.018117  9658 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:31.018293  9658 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:31.018362  9658 tablet_replica.cc:333] T 00000000000000000000000000000000 P 89cf7217107c4ada95fa8ab46ac1ac84: stopping tablet replica
I20260812 06:19:31.030328  9658 master.cc:584] Master@127.9.110.190:33309 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4799 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10106 ms total)

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