[==========] 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:20:11.540726  4842 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.186.190:41131
I20260812 06:20:11.541885  4842 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:20:11.542582  4842 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:11.549795  4851 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:11.549824  4848 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:20:11.550091  4849 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:20:11.550175  4842 server_base.cc:1061] running on GCE node
I20260812 06:20:11.550665  4842 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:11.550773  4842 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:20:11.550800  4842 hybrid_clock.cc:648] HybridClock initialized: now 1786515611550799 us; error 0 us; skew 500 ppm
I20260812 06:20:11.552831  4842 webserver.cc:533] Webserver started at http://127.4.186.190:38801/ using document root <none> and password file <none>
I20260812 06:20:11.553398  4842 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:11.553459  4842 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:11.553658  4842 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:11.555353  4842 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/master-0-root/instance:
uuid: "089aab9f0c454541b5250c1f84c47bd9"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-65mx"
I20260812 06:20:11.559226  4842 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:11.561555  4857 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:20:11.562798  4842 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:11.562958  4842 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/master-0-root
uuid: "089aab9f0c454541b5250c1f84c47bd9"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-65mx"
I20260812 06:20:11.563126  4842 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-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:20:11.592063  4842 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:11.592816  4842 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:20:11.593024  4842 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:11.601538  4842 rpc_server.cc:307] RPC server started. Bound to: 127.4.186.190:41131
I20260812 06:20:11.601557  4920 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.186.190:41131 every 8 connection(s)
I20260812 06:20:11.603986  4921 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:20:11.609863  4921 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9: Bootstrap starting.
I20260812 06:20:11.612445  4921 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:11.613512  4921 log.cc:826] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:11.615525  4921 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9: No bootstrap required, opened a new log
I20260812 06:20:11.618516  4921 raft_consensus.cc:359] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "089aab9f0c454541b5250c1f84c47bd9" member_type: VOTER }
I20260812 06:20:11.618698  4921 raft_consensus.cc:385] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:11.618742  4921 raft_consensus.cc:740] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 089aab9f0c454541b5250c1f84c47bd9, State: Initialized, Role: FOLLOWER
I20260812 06:20:11.619287  4921 consensus_queue.cc:260] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [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: "089aab9f0c454541b5250c1f84c47bd9" member_type: VOTER }
I20260812 06:20:11.619426  4921 raft_consensus.cc:399] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:11.619469  4921 raft_consensus.cc:493] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:11.619560  4921 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:11.620366  4921 raft_consensus.cc:515] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "089aab9f0c454541b5250c1f84c47bd9" member_type: VOTER }
I20260812 06:20:11.620857  4921 leader_election.cc:304] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [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: 089aab9f0c454541b5250c1f84c47bd9; no voters: 
I20260812 06:20:11.621227  4921 leader_election.cc:290] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:11.621374  4926 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:11.621647  4926 raft_consensus.cc:697] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 1 LEADER]: Becoming Leader. State: Replica: 089aab9f0c454541b5250c1f84c47bd9, State: Running, Role: LEADER
I20260812 06:20:11.622102  4926 consensus_queue.cc:237] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [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: "089aab9f0c454541b5250c1f84c47bd9" member_type: VOTER }
I20260812 06:20:11.622570  4921 sys_catalog.cc:565] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:11.624117  4927 sys_catalog.cc:455] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "089aab9f0c454541b5250c1f84c47bd9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "089aab9f0c454541b5250c1f84c47bd9" member_type: VOTER } }
I20260812 06:20:11.624256  4927 sys_catalog.cc:458] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:11.624532  4928 sys_catalog.cc:455] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 089aab9f0c454541b5250c1f84c47bd9. Latest consensus state: current_term: 1 leader_uuid: "089aab9f0c454541b5250c1f84c47bd9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "089aab9f0c454541b5250c1f84c47bd9" member_type: VOTER } }
I20260812 06:20:11.624715  4928 sys_catalog.cc:458] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:11.624722  4938 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:11.624943  4842 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:11.627154  4938 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:11.632078  4938 catalog_manager.cc:1383] Generated new cluster ID: 29877316729f49128b89c725607f34f6
I20260812 06:20:11.632169  4938 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:11.645699  4938 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:11.646627  4938 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:11.652297  4938 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9: Generated new TSK 0
I20260812 06:20:11.653046  4938 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:11.657797  4842 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:11.660732  4948 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:20:11.660857  4947 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:20:11.660916  4951 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:20:11.661391  4842 server_base.cc:1061] running on GCE node
I20260812 06:20:11.661576  4842 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:11.661624  4842 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:20:11.661648  4842 hybrid_clock.cc:648] HybridClock initialized: now 1786515611661647 us; error 0 us; skew 500 ppm
I20260812 06:20:11.662699  4842 webserver.cc:533] Webserver started at http://127.4.186.129:46549/ using document root <none> and password file <none>
I20260812 06:20:11.662881  4842 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:11.662943  4842 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:11.663015  4842 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:11.663467  4842 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/instance:
uuid: "87f24cdc81b0403088bd275ab6366974"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-65mx"
I20260812 06:20:11.665395  4842 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:11.666567  4956 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:20:11.666893  4842 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:11.666996  4842 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root
uuid: "87f24cdc81b0403088bd275ab6366974"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-65mx"
I20260812 06:20:11.667097  4842 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-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:20:11.680444  4842 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:11.681360  4842 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:11.681859  4842 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:11.682778  4842 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:11.682853  4842 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:11.682930  4842 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:11.682981  4842 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:11.690080  4842 rpc_server.cc:307] RPC server started. Bound to: 127.4.186.129:34161
I20260812 06:20:11.690155  5030 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.186.129:34161 every 8 connection(s)
I20260812 06:20:11.700632  5031 heartbeater.cc:344] Connected to a master server at 127.4.186.190:41131
I20260812 06:20:11.700912  5031 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:11.701375  5031 heartbeater.cc:507] Master 127.4.186.190:41131 requested a full tablet report, sending...
I20260812 06:20:11.702795  4877 ts_manager.cc:194] Registered new tserver with Master: 87f24cdc81b0403088bd275ab6366974 (127.4.186.129:34161)
I20260812 06:20:11.703162  4842 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012360075s
I20260812 06:20:11.704942  4877 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40704
I20260812 06:20:11.713653  4877 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40710:
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:20:11.730162  4986 tablet_service.cc:1511] Processing CreateTablet for tablet 391f9199095c44a1a3d8b636bce270d9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=53ed1523e2924e14b5131a218f93b9b7]), partition=
I20260812 06:20:11.730772  4986 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 391f9199095c44a1a3d8b636bce270d9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:11.733397  5046 tablet_bootstrap.cc:492] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Bootstrap starting.
I20260812 06:20:11.734601  5046 tablet_bootstrap.cc:654] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:11.735921  5046 tablet_bootstrap.cc:492] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: No bootstrap required, opened a new log
I20260812 06:20:11.736029  5046 ts_tablet_manager.cc:1403] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:11.736604  5046 raft_consensus.cc:359] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f24cdc81b0403088bd275ab6366974" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 34161 } }
I20260812 06:20:11.736734  5046 raft_consensus.cc:385] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:11.736768  5046 raft_consensus.cc:740] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 87f24cdc81b0403088bd275ab6366974, State: Initialized, Role: FOLLOWER
I20260812 06:20:11.736903  5046 consensus_queue.cc:260] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [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: "87f24cdc81b0403088bd275ab6366974" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 34161 } }
I20260812 06:20:11.737015  5046 raft_consensus.cc:399] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:11.737061  5046 raft_consensus.cc:493] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:11.737111  5046 raft_consensus.cc:3060] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:11.738090  5046 raft_consensus.cc:515] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f24cdc81b0403088bd275ab6366974" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 34161 } }
I20260812 06:20:11.738250  5046 leader_election.cc:304] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [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: 87f24cdc81b0403088bd275ab6366974; no voters: 
I20260812 06:20:11.738466  5046 leader_election.cc:290] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:11.738633  5048 raft_consensus.cc:2804] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:11.738788  5046 ts_tablet_manager.cc:1434] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:11.738915  5048 raft_consensus.cc:697] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 1 LEADER]: Becoming Leader. State: Replica: 87f24cdc81b0403088bd275ab6366974, State: Running, Role: LEADER
I20260812 06:20:11.739037  5031 heartbeater.cc:499] Master 127.4.186.190:41131 was elected leader, sending a full tablet report...
I20260812 06:20:11.739123  5048 consensus_queue.cc:237] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [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: "87f24cdc81b0403088bd275ab6366974" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 34161 } }
I20260812 06:20:11.741962  4877 catalog_manager.cc:5719] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 reported cstate change: term changed from 0 to 1, leader changed from <none> to 87f24cdc81b0403088bd275ab6366974 (127.4.186.129). New cstate: current_term: 1 leader_uuid: "87f24cdc81b0403088bd275ab6366974" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f24cdc81b0403088bd275ab6366974" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 34161 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:11.817885  4842 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.067s	user 0.026s	sys 0.008s
I20260812 06:20:11.941429  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushMRSOp(391f9199095c44a1a3d8b636bce270d9): perf score=15.086190
I20260812 06:20:12.108807  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushMRSOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.167s	user 0.112s	sys 0.053s Metrics: {"bytes_written":12389541,"cfile_init":1,"compiler_manager_pool.queue_time_us":209,"delete_count":0,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":288,"dirs.run_wall_time_us":1048,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41237,"lbm_writes_lt_1ms":659,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":75008,"thread_start_us":137,"threads_started":1,"update_count":1510}
I20260812 06:20:12.110160  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling LogGCOp(391f9199095c44a1a3d8b636bce270d9): free 11976772 bytes of WAL
I20260812 06:20:12.110491  4961 log_reader.cc:385] T 391f9199095c44a1a3d8b636bce270d9: removed 1 log segments from log reader
I20260812 06:20:12.110591  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000001 (ops 1-6)
I20260812 06:20:12.114423  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: LogGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:12.114965  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:12.135193  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":5512,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:20:12.135696  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9): 12308960 bytes on disk
I20260812 06:20:12.136346  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.136849  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:12.152412  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.153053  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:12.337085  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.184s	user 0.147s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733844,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":974,"lbm_read_time_us":11584,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31604,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"thread_start_us":403,"threads_started":5,"update_count":2500}
I20260812 06:20:12.337702  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=10.126437
I20260812 06:20:12.381407  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.043s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16073,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.381886  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:12.392974  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.393494  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:12.521399  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.128s	user 0.088s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":8756,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25292,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:20:12.521975  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=10.126437
I20260812 06:20:12.566609  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.044s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16176,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.567224  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:12.578338  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.578860  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:12.710485  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.131s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":997,"lbm_read_time_us":8095,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27433,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.711090  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=10.126437
I20260812 06:20:12.767179  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.056s	user 0.019s	sys 0.035s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21949,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.767807  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:12.778909  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.779392  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:12.928435  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.149s	user 0.121s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1678,"lbm_read_time_us":11606,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24636,"lbm_writes_lt_1ms":443,"mutex_wait_us":500,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.929205  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=10.126437
I20260812 06:20:12.977546  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.048s	user 0.012s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15960,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.978065  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:12.991374  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.991912  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:13.124495  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.132s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1612,"lbm_read_time_us":9709,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27173,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.125329  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=10.126437
I20260812 06:20:13.160915  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.035s	user 0.012s	sys 0.022s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":15317,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.161484  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.179040  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.179504  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:13.306236  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.127s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631316,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":9432,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24290,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:13.306852  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=10.126437
I20260812 06:20:13.353701  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18161,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.354178  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.364995  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.365715  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushMRSOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:13.393224  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushMRSOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1782,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1392,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:13.394089  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling LogGCOp(391f9199095c44a1a3d8b636bce270d9): free 120553376 bytes of WAL
I20260812 06:20:13.394384  4961 log_reader.cc:385] T 391f9199095c44a1a3d8b636bce270d9: removed 12 log segments from log reader
I20260812 06:20:13.394446  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000002 (ops 7-11)
I20260812 06:20:13.394486  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000003 (ops 12-16)
I20260812 06:20:13.394518  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000004 (ops 17-21)
I20260812 06:20:13.394549  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000005 (ops 22-26)
I20260812 06:20:13.394572  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000006 (ops 27-31)
I20260812 06:20:13.394601  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000007 (ops 32-36)
I20260812 06:20:13.394644  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000008 (ops 37-41)
I20260812 06:20:13.394670  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000009 (ops 42-46)
I20260812 06:20:13.394699  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000010 (ops 47-50)
I20260812 06:20:13.394721  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000011 (ops 51-55)
I20260812 06:20:13.394742  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000012 (ops 56-60)
I20260812 06:20:13.394771  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000013 (ops 61-64)
I20260812 06:20:13.426795  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: LogGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:13.427400  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.448884  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.021s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.449420  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.460276  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.460891  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9): 463 bytes on disk
I20260812 06:20:13.461571  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":123,"lbm_reads_lt_1ms":4}
I20260812 06:20:13.462234  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:13.645560  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.183s	user 0.131s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":718,"lbm_read_time_us":11652,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36725,"lbm_writes_lt_1ms":643,"mutex_wait_us":266,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:20:13.647903  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:13.702296  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.054s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23439,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.702955  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.725564  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.022s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.726099  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.741119  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4580,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.742277  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:13.910353  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.167s	user 0.136s	sys 0.029s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":358,"lbm_read_time_us":12240,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35290,"lbm_writes_lt_1ms":643,"mutex_wait_us":74,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3000}
I20260812 06:20:13.911058  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:13.970937  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.060s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28122,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.971678  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:13.985188  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.985646  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:14.166640  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.181s	user 0.135s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":896,"lbm_read_time_us":11448,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32743,"lbm_writes_lt_1ms":543,"mutex_wait_us":247,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:20:14.167234  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:14.227849  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.060s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26176,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:14.228365  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:14.240724  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4476,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.241546  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:14.456864  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.215s	user 0.131s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":650,"lbm_read_time_us":14190,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36750,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2500}
I20260812 06:20:14.457623  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:14.501359  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.043s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18577,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:14.501999  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:14.661718  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.159s	user 0.116s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1029,"lbm_read_time_us":11515,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24317,"lbm_writes_lt_1ms":443,"mutex_wait_us":444,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:20:14.662569  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=11.118625
I20260812 06:20:14.701542  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.039s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":16605,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":1550}
I20260812 06:20:14.702095  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:14.718232  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.016s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.718701  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:14.728860  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3742,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:14.729369  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:14.919137  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.190s	user 0.121s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733839,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1489,"lbm_read_time_us":13444,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29739,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":206976,"update_count":2500}
I20260812 06:20:14.919817  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=11.118625
I20260812 06:20:14.964509  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.044s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17156,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:14.965364  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:14.989168  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.024s	user 0.005s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:14.989785  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:15.000442  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.001016  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushMRSOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:15.032063  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushMRSOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1515,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1851,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:15.032935  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling LogGCOp(391f9199095c44a1a3d8b636bce270d9): free 133024366 bytes of WAL
I20260812 06:20:15.033185  4961 log_reader.cc:385] T 391f9199095c44a1a3d8b636bce270d9: removed 13 log segments from log reader
I20260812 06:20:15.033232  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000014 (ops 65-69)
I20260812 06:20:15.033262  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000015 (ops 70-74)
I20260812 06:20:15.033324  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000016 (ops 75-79)
I20260812 06:20:15.033360  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000017 (ops 80-84)
I20260812 06:20:15.033403  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000018 (ops 85-89)
I20260812 06:20:15.033439  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000019 (ops 90-94)
I20260812 06:20:15.033483  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000020 (ops 95-99)
I20260812 06:20:15.033540  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000021 (ops 100-104)
I20260812 06:20:15.033622  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000022 (ops 105-108)
I20260812 06:20:15.033684  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000023 (ops 109-113)
I20260812 06:20:15.033740  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000024 (ops 114-118)
I20260812 06:20:15.033782  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000025 (ops 119-123)
I20260812 06:20:15.033818  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000026 (ops 124-128)
I20260812 06:20:15.064359  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: LogGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.031s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:20:15.068365  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9): 492 bytes on disk
I20260812 06:20:15.069020  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:20:15.069880  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:15.092916  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.023s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4184707,"delete_count":0,"lbm_write_time_us":6849,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:20:15.093436  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:15.106122  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:20:15.106604  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:15.332901  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.226s	user 0.158s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938894,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":703,"lbm_read_time_us":15036,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38625,"lbm_writes_lt_1ms":743,"mutex_wait_us":1472,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:20:15.333580  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:15.398451  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.065s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24481,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.399242  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:15.413621  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.414346  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:15.602023  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.187s	user 0.125s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":302,"lbm_read_time_us":14142,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29060,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:20:15.602741  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:15.661329  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.058s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.661871  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:15.674198  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.674908  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:15.849246  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.174s	user 0.111s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":11626,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29490,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:20:15.849963  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:15.908207  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.058s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.908919  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:15.919934  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.920410  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:16.104535  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.184s	user 0.128s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":12820,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30244,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:16.105180  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:16.154625  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.049s	user 0.047s	sys 0.000s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21870,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.155169  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:16.176772  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.021s	user 0.007s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.177511  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:16.358917  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.181s	user 0.126s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1036,"lbm_read_time_us":10982,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31982,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:20:16.359519  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:16.403612  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.044s	user 0.032s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19285,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.404156  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:16.420423  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.421123  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:16.608417  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.187s	user 0.125s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":11395,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30800,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:20:16.609248  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=14.095187
I20260812 06:20:16.659536  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21945,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.660144  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:16.673043  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.673676  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushMRSOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:16.707914  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushMRSOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1357,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1600,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:16.708812  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling LogGCOp(391f9199095c44a1a3d8b636bce270d9): free 133024651 bytes of WAL
I20260812 06:20:16.709050  4961 log_reader.cc:385] T 391f9199095c44a1a3d8b636bce270d9: removed 13 log segments from log reader
I20260812 06:20:16.709103  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000027 (ops 129-133)
I20260812 06:20:16.709159  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000028 (ops 134-138)
I20260812 06:20:16.709208  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000029 (ops 139-143)
I20260812 06:20:16.709270  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000030 (ops 144-148)
I20260812 06:20:16.709309  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000031 (ops 149-153)
I20260812 06:20:16.709373  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000032 (ops 154-158)
I20260812 06:20:16.709416  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000033 (ops 159-163)
I20260812 06:20:16.709457  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000034 (ops 164-168)
I20260812 06:20:16.709496  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000035 (ops 169-173)
I20260812 06:20:16.709535  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000036 (ops 174-178)
I20260812 06:20:16.709596  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000037 (ops 179-183)
I20260812 06:20:16.709636  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000038 (ops 184-188)
I20260812 06:20:16.709700  4961 log.cc:1079] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/391f9199095c44a1a3d8b636bce270d9/wal-000000039 (ops 189-192)
I20260812 06:20:16.740357  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: LogGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:16.740831  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9): 493 bytes on disk
I20260812 06:20:16.741312  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: UndoDeltaBlockGCOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.741994  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=3.181125
I20260812 06:20:16.763347  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.021s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7624,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:16.763782  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9): perf score=2.188937
I20260812 06:20:16.773813  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: FlushDeltaMemStoresOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3711,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.774398  5032 maintenance_manager.cc:419] P 87f24cdc81b0403088bd275ab6366974: Scheduling MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9): perf score=1.000000
I20260812 06:20:16.878747  4842 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.061s	user 1.925s	sys 0.117s
I20260812 06:20:17.011760  4842 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.132s	user 0.001s	sys 0.000s
I20260812 06:20:17.012478  4842 tablet_server.cc:179] TabletServer@127.4.186.129:0 shutting down...
I20260812 06:20:17.022544  4961 maintenance_manager.cc:643] P 87f24cdc81b0403088bd275ab6366974: MajorDeltaCompactionOp(391f9199095c44a1a3d8b636bce270d9) complete. Timing: real 0.248s	user 0.163s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938772,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":480,"lbm_read_time_us":16102,"lbm_reads_lt_1ms":770,"lbm_write_time_us":46592,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:20:17.023204  4842 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:17.023610  4842 tablet_replica.cc:333] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974: stopping tablet replica
I20260812 06:20:17.023887  4842 raft_consensus.cc:2243] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:17.024174  4842 raft_consensus.cc:2272] T 391f9199095c44a1a3d8b636bce270d9 P 87f24cdc81b0403088bd275ab6366974 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:17.041941  4842 tablet_server.cc:196] TabletServer@127.4.186.129:0 shutdown complete.
I20260812 06:20:17.083422  4842 master.cc:562] Master@127.4.186.190:41131 shutting down...
I20260812 06:20:17.087671  4842 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:17.087868  4842 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:17.087925  4842 tablet_replica.cc:333] T 00000000000000000000000000000000 P 089aab9f0c454541b5250c1f84c47bd9: stopping tablet replica
I20260812 06:20:17.100406  4842 master.cc:584] Master@127.4.186.190:41131 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5651 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:17.204643  4842 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.186.190:33667
I20260812 06:20:17.205041  4842 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:17.207715  5070 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:20:17.207715  5069 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:20:17.207856  5073 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:20:17.207865  4842 server_base.cc:1061] running on GCE node
I20260812 06:20:17.208161  4842 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:17.208210  4842 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:20:17.208226  4842 hybrid_clock.cc:648] HybridClock initialized: now 1786515617208226 us; error 0 us; skew 500 ppm
I20260812 06:20:17.214133  4842 webserver.cc:533] Webserver started at http://127.4.186.190:39403/ using document root <none> and password file <none>
I20260812 06:20:17.214361  4842 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:17.214437  4842 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:17.214527  4842 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:17.214972  4842 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/master-0-root/instance:
uuid: "af8e71446e0e41808cd64df3336d880a"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-65mx"
I20260812 06:20:17.216697  4842 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:17.217792  5079 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:20:17.218082  4842 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:17.218190  4842 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/master-0-root
uuid: "af8e71446e0e41808cd64df3336d880a"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-65mx"
I20260812 06:20:17.218290  4842 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-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:20:17.225602  4842 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:17.226050  4842 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:17.230773  4842 rpc_server.cc:307] RPC server started. Bound to: 127.4.186.190:33667
I20260812 06:20:17.237255  5136 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.186.190:33667 every 8 connection(s)
I20260812 06:20:17.237267  5137 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:20:17.239351  5137 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a: Bootstrap starting.
I20260812 06:20:17.240306  5137 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:17.241561  5137 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a: No bootstrap required, opened a new log
I20260812 06:20:17.242036  5137 raft_consensus.cc:359] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af8e71446e0e41808cd64df3336d880a" member_type: VOTER }
I20260812 06:20:17.242130  5137 raft_consensus.cc:385] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:17.242152  5137 raft_consensus.cc:740] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af8e71446e0e41808cd64df3336d880a, State: Initialized, Role: FOLLOWER
I20260812 06:20:17.242352  5137 consensus_queue.cc:260] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [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: "af8e71446e0e41808cd64df3336d880a" member_type: VOTER }
I20260812 06:20:17.242431  5137 raft_consensus.cc:399] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:17.242492  5137 raft_consensus.cc:493] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:17.242545  5137 raft_consensus.cc:3060] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:17.243436  5137 raft_consensus.cc:515] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af8e71446e0e41808cd64df3336d880a" member_type: VOTER }
I20260812 06:20:17.243640  5137 leader_election.cc:304] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [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: af8e71446e0e41808cd64df3336d880a; no voters: 
I20260812 06:20:17.243921  5137 leader_election.cc:290] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:17.244127  5140 raft_consensus.cc:2804] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:17.244354  5140 raft_consensus.cc:697] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 1 LEADER]: Becoming Leader. State: Replica: af8e71446e0e41808cd64df3336d880a, State: Running, Role: LEADER
I20260812 06:20:17.244428  5137 sys_catalog.cc:565] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:17.244601  5140 consensus_queue.cc:237] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [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: "af8e71446e0e41808cd64df3336d880a" member_type: VOTER }
I20260812 06:20:17.245087  5142 sys_catalog.cc:455] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [sys.catalog]: SysCatalogTable state changed. Reason: New leader af8e71446e0e41808cd64df3336d880a. Latest consensus state: current_term: 1 leader_uuid: "af8e71446e0e41808cd64df3336d880a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af8e71446e0e41808cd64df3336d880a" member_type: VOTER } }
I20260812 06:20:17.245198  5142 sys_catalog.cc:458] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:17.245414  5141 sys_catalog.cc:455] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "af8e71446e0e41808cd64df3336d880a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af8e71446e0e41808cd64df3336d880a" member_type: VOTER } }
I20260812 06:20:17.245549  5141 sys_catalog.cc:458] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:17.245961  5147 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:17.246771  5147 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:17.247030  4842 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:17.248723  5147 catalog_manager.cc:1383] Generated new cluster ID: 6c415762aea942c2b63510b8df02bd9e
I20260812 06:20:17.248781  5147 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:17.257735  5147 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:17.258271  5147 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:17.265640  5147 catalog_manager.cc:6092] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a: Generated new TSK 0
I20260812 06:20:17.265877  5147 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:17.280198  4842 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:17.282395  5160 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:20:17.282490  5161 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:20:17.282397  5165 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:20:17.282611  4842 server_base.cc:1061] running on GCE node
I20260812 06:20:17.282867  4842 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:17.282934  4842 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:20:17.282958  4842 hybrid_clock.cc:648] HybridClock initialized: now 1786515617282959 us; error 0 us; skew 500 ppm
I20260812 06:20:17.283876  4842 webserver.cc:533] Webserver started at http://127.4.186.129:35911/ using document root <none> and password file <none>
I20260812 06:20:17.284068  4842 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:17.284142  4842 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:17.284250  4842 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:17.284770  4842 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/instance:
uuid: "e1d88bd8956e4443ae2cf0f7ff7d4e21"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-65mx"
I20260812 06:20:17.286429  4842 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:17.287472  5171 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:20:17.287822  4842 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:17.287910  4842 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root
uuid: "e1d88bd8956e4443ae2cf0f7ff7d4e21"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-65mx"
I20260812 06:20:17.288020  4842 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-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:20:17.303680  4842 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:17.304087  4842 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:17.304538  4842 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:17.305318  4842 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:17.305378  4842 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.305457  4842 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:17.305493  4842 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.312268  4842 rpc_server.cc:307] RPC server started. Bound to: 127.4.186.129:41241
I20260812 06:20:17.314139  5246 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.186.129:41241 every 8 connection(s)
I20260812 06:20:17.319973  5249 heartbeater.cc:344] Connected to a master server at 127.4.186.190:33667
I20260812 06:20:17.320130  5249 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:17.320441  5249 heartbeater.cc:507] Master 127.4.186.190:33667 requested a full tablet report, sending...
I20260812 06:20:17.321198  5099 ts_manager.cc:194] Registered new tserver with Master: e1d88bd8956e4443ae2cf0f7ff7d4e21 (127.4.186.129:41241)
I20260812 06:20:17.322088  5099 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52934
I20260812 06:20:17.322118  4842 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008988561s
I20260812 06:20:17.331225  5099 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52942:
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:20:17.342067  5205 tablet_service.cc:1511] Processing CreateTablet for tablet 62be7c69d7bf46a9a583b1c49b904604 (DEFAULT_TABLE table=heavy-update-compaction-test [id=53328f05c3484e6fa5650d5ed2be8da3]), partition=
I20260812 06:20:17.342397  5205 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 62be7c69d7bf46a9a583b1c49b904604. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:17.344923  5261 tablet_bootstrap.cc:492] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Bootstrap starting.
I20260812 06:20:17.346364  5261 tablet_bootstrap.cc:654] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:17.347795  5261 tablet_bootstrap.cc:492] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: No bootstrap required, opened a new log
I20260812 06:20:17.347918  5261 ts_tablet_manager.cc:1403] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:17.348592  5261 raft_consensus.cc:359] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1d88bd8956e4443ae2cf0f7ff7d4e21" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 41241 } }
I20260812 06:20:17.348726  5261 raft_consensus.cc:385] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:17.348770  5261 raft_consensus.cc:740] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e1d88bd8956e4443ae2cf0f7ff7d4e21, State: Initialized, Role: FOLLOWER
I20260812 06:20:17.348940  5261 consensus_queue.cc:260] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [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: "e1d88bd8956e4443ae2cf0f7ff7d4e21" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 41241 } }
I20260812 06:20:17.349053  5261 raft_consensus.cc:399] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:17.349105  5261 raft_consensus.cc:493] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:17.349166  5261 raft_consensus.cc:3060] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:17.350449  5261 raft_consensus.cc:515] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1d88bd8956e4443ae2cf0f7ff7d4e21" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 41241 } }
I20260812 06:20:17.350633  5261 leader_election.cc:304] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [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: e1d88bd8956e4443ae2cf0f7ff7d4e21; no voters: 
I20260812 06:20:17.350895  5261 leader_election.cc:290] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:17.350993  5263 raft_consensus.cc:2804] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:17.351174  5263 raft_consensus.cc:697] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 1 LEADER]: Becoming Leader. State: Replica: e1d88bd8956e4443ae2cf0f7ff7d4e21, State: Running, Role: LEADER
I20260812 06:20:17.351269  5261 ts_tablet_manager.cc:1434] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:17.351325  5263 consensus_queue.cc:237] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [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: "e1d88bd8956e4443ae2cf0f7ff7d4e21" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 41241 } }
I20260812 06:20:17.351454  5249 heartbeater.cc:499] Master 127.4.186.190:33667 was elected leader, sending a full tablet report...
I20260812 06:20:17.352855  5099 catalog_manager.cc:5719] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 reported cstate change: term changed from 0 to 1, leader changed from <none> to e1d88bd8956e4443ae2cf0f7ff7d4e21 (127.4.186.129). New cstate: current_term: 1 leader_uuid: "e1d88bd8956e4443ae2cf0f7ff7d4e21" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1d88bd8956e4443ae2cf0f7ff7d4e21" member_type: VOTER last_known_addr { host: "127.4.186.129" port: 41241 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:17.416003  4842 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.017s	sys 0.006s
I20260812 06:20:17.564822  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604): perf score=19.054940
I20260812 06:20:17.730851  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.166s	user 0.131s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":862,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42367,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:17.731528  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling LogGCOp(62be7c69d7bf46a9a583b1c49b904604): free 20743880 bytes of WAL
I20260812 06:20:17.731781  5176 log_reader.cc:385] T 62be7c69d7bf46a9a583b1c49b904604: removed 2 log segments from log reader
I20260812 06:20:17.731824  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000001 (ops 1-6)
I20260812 06:20:17.731856  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000002 (ops 7-11)
I20260812 06:20:17.736241  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: LogGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:17.736711  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604): 16411393 bytes on disk
I20260812 06:20:17.737182  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.737603  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:17.754128  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6545,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.754593  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:17.915500  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.161s	user 0.103s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":523,"lbm_read_time_us":11618,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25714,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":316,"threads_started":5,"update_count":2000}
I20260812 06:20:17.916085  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=11.118625
I20260812 06:20:17.963392  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.047s	user 0.037s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15791,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:17.964076  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:17.976192  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4432,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:20:17.976759  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:17.988127  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3815483,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:20:17.988746  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:18.167920  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.179s	user 0.111s	sys 0.065s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":348,"lbm_read_time_us":14216,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29192,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:20:18.168617  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:18.237615  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.069s	user 0.028s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23538,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.238130  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:18.249608  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.250151  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:18.430678  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.180s	user 0.114s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":789,"lbm_read_time_us":12600,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30551,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:18.431414  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:18.494814  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.063s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.495394  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:18.506431  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.506907  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:18.697281  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.190s	user 0.117s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":12888,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32057,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:18.697791  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=11.118625
I20260812 06:20:18.733897  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16006,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.734565  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:18.751178  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5615,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.751725  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:18.932824  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.181s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2762,"lbm_read_time_us":9985,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24865,"lbm_writes_lt_1ms":443,"mutex_wait_us":1336,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:20:18.933521  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:18.985255  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.052s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20812,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.985742  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:18.996958  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.997790  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:19.027973  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1412,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2015,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:19.028671  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling LogGCOp(62be7c69d7bf46a9a583b1c49b904604): free 115943180 bytes of WAL
I20260812 06:20:19.028946  5176 log_reader.cc:385] T 62be7c69d7bf46a9a583b1c49b904604: removed 11 log segments from log reader
I20260812 06:20:19.029026  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000003 (ops 12-16)
I20260812 06:20:19.029065  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000004 (ops 17-21)
I20260812 06:20:19.029093  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000005 (ops 22-26)
I20260812 06:20:19.029119  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000006 (ops 27-31)
I20260812 06:20:19.029142  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000007 (ops 32-36)
I20260812 06:20:19.029165  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000008 (ops 37-41)
I20260812 06:20:19.029202  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000009 (ops 42-46)
I20260812 06:20:19.029235  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000010 (ops 47-51)
I20260812 06:20:19.029263  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000011 (ops 52-56)
I20260812 06:20:19.029295  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000012 (ops 57-61)
I20260812 06:20:19.029318  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000013 (ops 62-66)
I20260812 06:20:19.060163  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: LogGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:19.060673  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:19.087011  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.087553  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:19.098912  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.099411  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604): 447 bytes on disk
I20260812 06:20:19.100031  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":139,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.100852  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:19.332955  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.232s	user 0.177s	sys 0.050s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":359,"lbm_read_time_us":14688,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38011,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":94,"threads_started":1,"update_count":3500}
I20260812 06:20:19.333767  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=18.063937
I20260812 06:20:19.401851  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.068s	user 0.039s	sys 0.028s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":25589,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:19.402463  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:19.418418  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.418885  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:19.648808  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.230s	user 0.153s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1071,"lbm_read_time_us":16152,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36062,"lbm_writes_lt_1ms":643,"mutex_wait_us":408,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3000}
I20260812 06:20:19.649603  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:19.693272  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.043s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18986,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.694077  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:19.839985  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.146s	user 0.102s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":937,"lbm_read_time_us":10116,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24841,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:20:19.840679  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=10.126437
I20260812 06:20:19.887024  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.046s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18867,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.887641  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:19.914001  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.026s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.914539  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:19.926573  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.927112  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:20.116645  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.189s	user 0.116s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":185,"lbm_read_time_us":9917,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28943,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:20:20.117771  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:20.171815  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.054s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20951,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.172389  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:20.185505  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.186010  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:20.364373  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.178s	user 0.117s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":11364,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33413,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:20:20.365149  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:20.417089  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.052s	user 0.040s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21973,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.417632  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:20.429356  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.430019  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:20.578763  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.149s	user 0.112s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":10545,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29391,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:20:20.579519  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=11.118625
I20260812 06:20:20.612851  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.033s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13846,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:20.613435  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:20.633518  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.020s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6004,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":450}
I20260812 06:20:20.634089  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:20.687311  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.053s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1354,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1959,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:20.688287  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling LogGCOp(62be7c69d7bf46a9a583b1c49b904604): free 124710298 bytes of WAL
I20260812 06:20:20.688685  5176 log_reader.cc:385] T 62be7c69d7bf46a9a583b1c49b904604: removed 12 log segments from log reader
I20260812 06:20:20.688772  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000014 (ops 67-71)
I20260812 06:20:20.688838  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000015 (ops 72-76)
I20260812 06:20:20.688880  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000016 (ops 77-81)
I20260812 06:20:20.688920  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000017 (ops 82-86)
I20260812 06:20:20.688959  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000018 (ops 87-91)
I20260812 06:20:20.689025  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000019 (ops 92-96)
I20260812 06:20:20.689061  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000020 (ops 97-101)
I20260812 06:20:20.689107  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000021 (ops 102-106)
I20260812 06:20:20.689144  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000022 (ops 107-111)
I20260812 06:20:20.689190  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000023 (ops 112-116)
I20260812 06:20:20.689234  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000024 (ops 117-121)
I20260812 06:20:20.689280  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000025 (ops 122-126)
I20260812 06:20:20.720439  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: LogGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.032s	user 0.003s	sys 0.028s Metrics: {}
I20260812 06:20:20.721263  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604): 493 bytes on disk
I20260812 06:20:20.721815  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:20.722508  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=8.142062
I20260812 06:20:20.747166  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.024s	user 0.019s	sys 0.004s Metrics: {"bytes_written":9887068,"delete_count":0,"lbm_write_time_us":9980,"lbm_writes_lt_1ms":244,"reinsert_count":0,"update_count":1205}
I20260812 06:20:20.747650  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling LogGCOp(62be7c69d7bf46a9a583b1c49b904604): free 8767130 bytes of WAL
I20260812 06:20:20.747872  5176 log_reader.cc:385] T 62be7c69d7bf46a9a583b1c49b904604: removed 1 log segments from log reader
I20260812 06:20:20.747951  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000026 (ops 127-131)
I20260812 06:20:20.749854  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: LogGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:20.750159  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.196750
I20260812 06:20:20.783069  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.033s	user 0.007s	sys 0.005s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":3529,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:20:20.783725  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:20.800487  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.801213  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:21.071169  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.270s	user 0.169s	sys 0.092s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082236,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":927,"lbm_read_time_us":18458,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45186,"lbm_writes_lt_1ms":843,"mutex_wait_us":32,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":88832,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:20:21.071938  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=18.063937
I20260812 06:20:21.151289  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.079s	user 0.033s	sys 0.028s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29212,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:21.151801  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:21.164407  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.165015  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:21.379144  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.214s	user 0.143s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":17313,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32815,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":82176,"update_count":3000}
I20260812 06:20:21.379987  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=15.087375
I20260812 06:20:21.437079  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.057s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":26045,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:21.437747  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:21.450786  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4907,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.451239  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:21.616375  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.165s	user 0.112s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":11317,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28219,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:20:21.617209  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:21.676057  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.059s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19361,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.676766  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:21.687866  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.688391  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:21.874653  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.186s	user 0.124s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":12574,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29881,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2500}
I20260812 06:20:21.875540  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:21.941511  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.066s	user 0.025s	sys 0.034s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27210,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.942243  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:21.954286  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.954993  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:22.142740  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.188s	user 0.131s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1290,"lbm_read_time_us":12781,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30735,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:20:22.143461  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=14.095187
I20260812 06:20:22.201953  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.058s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28793,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.202565  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:22.223474  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.021s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.224191  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:22.259886  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushMRSOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.035s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1519,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2153,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:22.260725  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling LogGCOp(62be7c69d7bf46a9a583b1c49b904604): free 112239561 bytes of WAL
I20260812 06:20:22.261006  5176 log_reader.cc:385] T 62be7c69d7bf46a9a583b1c49b904604: removed 11 log segments from log reader
I20260812 06:20:22.261073  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000027 (ops 132-136)
I20260812 06:20:22.261114  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000028 (ops 137-140)
I20260812 06:20:22.261142  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000029 (ops 141-145)
I20260812 06:20:22.261175  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000030 (ops 146-150)
I20260812 06:20:22.261198  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000031 (ops 151-155)
I20260812 06:20:22.261219  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000032 (ops 156-160)
I20260812 06:20:22.261247  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000033 (ops 161-165)
I20260812 06:20:22.261269  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000034 (ops 166-170)
I20260812 06:20:22.261300  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000035 (ops 171-175)
I20260812 06:20:22.261333  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000036 (ops 176-180)
I20260812 06:20:22.261363  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000037 (ops 181-185)
I20260812 06:20:22.293514  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: LogGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.033s	user 0.001s	sys 0.029s Metrics: {}
I20260812 06:20:22.294032  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604): 461 bytes on disk
I20260812 06:20:22.294605  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: UndoDeltaBlockGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.295326  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:22.321576  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.322038  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling LogGCOp(62be7c69d7bf46a9a583b1c49b904604): free 12017952 bytes of WAL
I20260812 06:20:22.322245  5176 log_reader.cc:385] T 62be7c69d7bf46a9a583b1c49b904604: removed 1 log segments from log reader
I20260812 06:20:22.322288  5176 log.cc:1079] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: Deleting log segment in path: /tmp/dist-test-taskw_BTdL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611528197-4842-0/minicluster-data/ts-0-root/wals/62be7c69d7bf46a9a583b1c49b904604/wal-000000038 (ops 186-190)
I20260812 06:20:22.324764  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: LogGCOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:22.325075  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=2.188937
I20260812 06:20:22.337512  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.338044  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604): perf score=1.000000
I20260812 06:20:22.566425  4842 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.150s	user 1.941s	sys 0.160s
I20260812 06:20:22.581820  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: MajorDeltaCompactionOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.244s	user 0.158s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1235,"lbm_read_time_us":17578,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39407,"lbm_writes_lt_1ms":743,"mutex_wait_us":73,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:20:22.585634  5250 maintenance_manager.cc:419] P e1d88bd8956e4443ae2cf0f7ff7d4e21: Scheduling FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604): perf score=18.063937
I20260812 06:20:22.636723  4842 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.070s	user 0.005s	sys 0.000s
I20260812 06:20:22.637434  4842 tablet_server.cc:179] TabletServer@127.4.186.129:0 shutting down...
I20260812 06:20:22.654958  5176 maintenance_manager.cc:643] P e1d88bd8956e4443ae2cf0f7ff7d4e21: FlushDeltaMemStoresOp(62be7c69d7bf46a9a583b1c49b904604) complete. Timing: real 0.069s	user 0.046s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31246,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:22.655722  4842 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:22.655987  4842 tablet_replica.cc:333] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21: stopping tablet replica
I20260812 06:20:22.656195  4842 raft_consensus.cc:2243] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.656386  4842 raft_consensus.cc:2272] T 62be7c69d7bf46a9a583b1c49b904604 P e1d88bd8956e4443ae2cf0f7ff7d4e21 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.670362  4842 tablet_server.cc:196] TabletServer@127.4.186.129:0 shutdown complete.
I20260812 06:20:22.673734  4842 master.cc:562] Master@127.4.186.190:33667 shutting down...
I20260812 06:20:22.677512  4842 raft_consensus.cc:2243] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.677716  4842 raft_consensus.cc:2272] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.677769  4842 tablet_replica.cc:333] T 00000000000000000000000000000000 P af8e71446e0e41808cd64df3336d880a: stopping tablet replica
I20260812 06:20:22.690834  4842 master.cc:584] Master@127.4.186.190:33667 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5591 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11243 ms total)

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