[==========] 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:15.913491  4021 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.237.126:33845
I20260812 06:20:15.914650  4021 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:15.915329  4021 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:15.922308  4026 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:15.922441  4030 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:15.922533  4021 server_base.cc:1061] running on GCE node
W20260812 06:20:15.922659  4027 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:15.923290  4021 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.923396  4021 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:15.923425  4021 hybrid_clock.cc:648] HybridClock initialized: now 1786515615923423 us; error 0 us; skew 500 ppm
I20260812 06:20:15.925547  4021 webserver.cc:533] Webserver started at http://127.3.237.126:44567/ using document root <none> and password file <none>
I20260812 06:20:15.926393  4021 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.926473  4021 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.926716  4021 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.928596  4021 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/master-0-root/instance:
uuid: "ea44c861f295490b99b6b3617bb91f2f"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-9zdj"
I20260812 06:20:15.932686  4021 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.004s
I20260812 06:20:15.935359  4036 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:15.936615  4021 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.000s
I20260812 06:20:15.936784  4021 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/master-0-root
uuid: "ea44c861f295490b99b6b3617bb91f2f"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-9zdj"
I20260812 06:20:15.936939  4021 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-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:15.962363  4021 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.963224  4021 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:15.963454  4021 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.973486  4021 rpc_server.cc:307] RPC server started. Bound to: 127.3.237.126:33845
I20260812 06:20:15.973547  4097 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.237.126:33845 every 8 connection(s)
I20260812 06:20:15.976418  4098 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:15.983135  4098 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: Bootstrap starting.
I20260812 06:20:15.985919  4098 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.986979  4098 log.cc:826] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:15.989205  4098 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: No bootstrap required, opened a new log
I20260812 06:20:15.992457  4098 raft_consensus.cc:359] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ea44c861f295490b99b6b3617bb91f2f" member_type: VOTER }
I20260812 06:20:15.992669  4098 raft_consensus.cc:385] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.992715  4098 raft_consensus.cc:740] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ea44c861f295490b99b6b3617bb91f2f, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.993341  4098 consensus_queue.cc:260] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [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: "ea44c861f295490b99b6b3617bb91f2f" member_type: VOTER }
I20260812 06:20:15.993506  4098 raft_consensus.cc:399] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.993558  4098 raft_consensus.cc:493] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.993729  4098 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.994714  4098 raft_consensus.cc:515] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ea44c861f295490b99b6b3617bb91f2f" member_type: VOTER }
I20260812 06:20:15.995204  4098 leader_election.cc:304] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [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: ea44c861f295490b99b6b3617bb91f2f; no voters: 
I20260812 06:20:15.995549  4098 leader_election.cc:290] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.995723  4103 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.996088  4103 raft_consensus.cc:697] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 1 LEADER]: Becoming Leader. State: Replica: ea44c861f295490b99b6b3617bb91f2f, State: Running, Role: LEADER
I20260812 06:20:15.996583  4103 consensus_queue.cc:237] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [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: "ea44c861f295490b99b6b3617bb91f2f" member_type: VOTER }
I20260812 06:20:15.996726  4098 sys_catalog.cc:565] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:15.998943  4104 sys_catalog.cc:455] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ea44c861f295490b99b6b3617bb91f2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ea44c861f295490b99b6b3617bb91f2f" member_type: VOTER } }
I20260812 06:20:15.999095  4104 sys_catalog.cc:458] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.999401  4021 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:15.999639  4105 sys_catalog.cc:455] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [sys.catalog]: SysCatalogTable state changed. Reason: New leader ea44c861f295490b99b6b3617bb91f2f. Latest consensus state: current_term: 1 leader_uuid: "ea44c861f295490b99b6b3617bb91f2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ea44c861f295490b99b6b3617bb91f2f" member_type: VOTER } }
I20260812 06:20:15.999724  4105 sys_catalog.cc:458] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [sys.catalog]: This master's current role is: LEADER
W20260812 06:20:16.001605  4119 catalog_manager.cc:1594] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:16.001744  4119 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:16.001816  4118 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:16.002696  4118 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:16.008867  4118 catalog_manager.cc:1383] Generated new cluster ID: 8bce498558024289a2ccbfb0eac0cba2
I20260812 06:20:16.008965  4118 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:16.024093  4118 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:16.025244  4118 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:16.031400  4118 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: Generated new TSK 0
I20260812 06:20:16.032243  4118 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:16.064558  4021 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.068078  4128 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:16.068222  4126 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:16.068382  4125 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:16.068547  4021 server_base.cc:1061] running on GCE node
I20260812 06:20:16.068765  4021 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.068811  4021 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:16.068828  4021 hybrid_clock.cc:648] HybridClock initialized: now 1786515616068828 us; error 0 us; skew 500 ppm
I20260812 06:20:16.069993  4021 webserver.cc:533] Webserver started at http://127.3.237.65:44045/ using document root <none> and password file <none>
I20260812 06:20:16.070205  4021 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.070279  4021 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.070372  4021 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.070823  4021 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/instance:
uuid: "5b19b32ad3e3411cb135126bbc08f39b"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-9zdj"
I20260812 06:20:16.072485  4021 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:16.073558  4134 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:16.073868  4021 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:16.073952  4021 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root
uuid: "5b19b32ad3e3411cb135126bbc08f39b"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-9zdj"
I20260812 06:20:16.074050  4021 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-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:16.093544  4021 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.094393  4021 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.094973  4021 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:16.095908  4021 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:16.095964  4021 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.096037  4021 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:16.096077  4021 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.103536  4021 rpc_server.cc:307] RPC server started. Bound to: 127.3.237.65:41613
I20260812 06:20:16.103557  4207 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.237.65:41613 every 8 connection(s)
I20260812 06:20:16.125715  4208 heartbeater.cc:344] Connected to a master server at 127.3.237.126:33845
I20260812 06:20:16.126027  4208 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:16.126543  4208 heartbeater.cc:507] Master 127.3.237.126:33845 requested a full tablet report, sending...
I20260812 06:20:16.128296  4052 ts_manager.cc:194] Registered new tserver with Master: 5b19b32ad3e3411cb135126bbc08f39b (127.3.237.65:41613)
I20260812 06:20:16.129033  4021 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.024739517s
I20260812 06:20:16.129984  4052 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34562
I20260812 06:20:16.140727  4052 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34574:
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:16.159195  4162 tablet_service.cc:1511] Processing CreateTablet for tablet df43cfbb4d4c44498b3f724a712ac7bd (DEFAULT_TABLE table=heavy-update-compaction-test [id=f34a3aa79a40421ab23dcf0f5218af72]), partition=
I20260812 06:20:16.159739  4162 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet df43cfbb4d4c44498b3f724a712ac7bd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:16.162727  4223 tablet_bootstrap.cc:492] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Bootstrap starting.
I20260812 06:20:16.163862  4223 tablet_bootstrap.cc:654] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.165337  4223 tablet_bootstrap.cc:492] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: No bootstrap required, opened a new log
I20260812 06:20:16.165444  4223 ts_tablet_manager.cc:1403] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:16.166152  4223 raft_consensus.cc:359] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b19b32ad3e3411cb135126bbc08f39b" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 41613 } }
I20260812 06:20:16.166339  4223 raft_consensus.cc:385] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.166440  4223 raft_consensus.cc:740] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b19b32ad3e3411cb135126bbc08f39b, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.166663  4223 consensus_queue.cc:260] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [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: "5b19b32ad3e3411cb135126bbc08f39b" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 41613 } }
I20260812 06:20:16.166821  4223 raft_consensus.cc:399] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.166931  4223 raft_consensus.cc:493] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.167002  4223 raft_consensus.cc:3060] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.167868  4223 raft_consensus.cc:515] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b19b32ad3e3411cb135126bbc08f39b" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 41613 } }
I20260812 06:20:16.168056  4223 leader_election.cc:304] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [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: 5b19b32ad3e3411cb135126bbc08f39b; no voters: 
I20260812 06:20:16.168365  4223 leader_election.cc:290] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.168484  4225 raft_consensus.cc:2804] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.168737  4225 raft_consensus.cc:697] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 1 LEADER]: Becoming Leader. State: Replica: 5b19b32ad3e3411cb135126bbc08f39b, State: Running, Role: LEADER
I20260812 06:20:16.168800  4223 ts_tablet_manager.cc:1434] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:20:16.169173  4208 heartbeater.cc:499] Master 127.3.237.126:33845 was elected leader, sending a full tablet report...
I20260812 06:20:16.169308  4225 consensus_queue.cc:237] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [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: "5b19b32ad3e3411cb135126bbc08f39b" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 41613 } }
I20260812 06:20:16.172643  4056 catalog_manager.cc:5719] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b19b32ad3e3411cb135126bbc08f39b (127.3.237.65). New cstate: current_term: 1 leader_uuid: "5b19b32ad3e3411cb135126bbc08f39b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b19b32ad3e3411cb135126bbc08f39b" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 41613 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:16.246445  4021 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.020s	sys 0.012s
I20260812 06:20:16.354875  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=11.117440
I20260812 06:20:16.490306  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.135s	user 0.126s	sys 0.008s Metrics: {"bytes_written":8410199,"cfile_init":1,"compiler_manager_pool.queue_time_us":343,"delete_count":0,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":306,"dirs.run_wall_time_us":1150,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":28856,"lbm_writes_lt_1ms":472,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":274816,"thread_start_us":165,"threads_started":1,"update_count":1025}
I20260812 06:20:16.491528  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd): free 11976772 bytes of WAL
I20260812 06:20:16.491884  4140 log_reader.cc:385] T df43cfbb4d4c44498b3f724a712ac7bd: removed 1 log segments from log reader
I20260812 06:20:16.491963  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000001 (ops 1-6)
I20260812 06:20:16.495680  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:16.496171  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:16.512121  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:20:16.513044  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd): 8616793 bytes on disk
I20260812 06:20:16.513881  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.514484  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:16.640512  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.126s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16118642,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1609,"lbm_read_time_us":8993,"lbm_reads_lt_1ms":350,"lbm_write_time_us":22160,"lbm_writes_lt_1ms":333,"mutex_wait_us":61,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":727,"threads_started":5,"update_count":1450}
I20260812 06:20:16.641417  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=7.149875
I20260812 06:20:16.669404  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.028s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12001,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:16.670097  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:16.687786  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6339,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.688360  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:16.821857  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.133s	user 0.085s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":945,"lbm_read_time_us":9252,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21678,"lbm_writes_lt_1ms":343,"mutex_wait_us":62,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:20:16.822597  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:16.868310  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.046s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16990,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.868818  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:16.882316  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.882823  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:17.029383  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.146s	user 0.110s	sys 0.036s 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":354,"lbm_read_time_us":10890,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28786,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:20:17.030164  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:17.082965  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.053s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18540,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.083618  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:17.097028  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.097522  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:17.247483  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.150s	user 0.129s	sys 0.021s 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":358,"lbm_read_time_us":10587,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29829,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38272,"update_count":2000}
I20260812 06:20:17.248188  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:17.295756  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.047s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16792,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.296376  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:17.308092  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.308635  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:17.468910  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.160s	user 0.110s	sys 0.045s 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":170,"lbm_read_time_us":11752,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26102,"lbm_writes_lt_1ms":443,"mutex_wait_us":102,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:20:17.469667  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:17.523016  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.053s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17060,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.523576  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:17.534775  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.535260  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:17.681823  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.146s	user 0.115s	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":288,"lbm_read_time_us":11095,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28182,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:20:17.682729  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=11.118625
I20260812 06:20:17.720866  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.038s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16047,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:17.721455  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:17.739506  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6182,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.740063  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:17.867794  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.128s	user 0.108s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":984,"lbm_read_time_us":8115,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24933,"lbm_writes_lt_1ms":443,"mutex_wait_us":402,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.868541  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:17.908391  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.040s	user 0.023s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17006,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.909122  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:17.921662  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.922269  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:17.955469  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1580,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1937,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:17.956423  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd): free 120553377 bytes of WAL
I20260812 06:20:17.956707  4140 log_reader.cc:385] T df43cfbb4d4c44498b3f724a712ac7bd: removed 12 log segments from log reader
I20260812 06:20:17.956784  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000002 (ops 7-11)
I20260812 06:20:17.956842  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000003 (ops 12-16)
I20260812 06:20:17.956902  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000004 (ops 17-20)
I20260812 06:20:17.956943  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000005 (ops 21-25)
I20260812 06:20:17.956979  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000006 (ops 26-30)
I20260812 06:20:17.957017  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000007 (ops 31-34)
I20260812 06:20:17.957053  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000008 (ops 35-39)
I20260812 06:20:17.957090  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000009 (ops 40-44)
I20260812 06:20:17.957127  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000010 (ops 45-49)
I20260812 06:20:17.957163  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000011 (ops 50-54)
I20260812 06:20:17.957202  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000012 (ops 55-59)
I20260812 06:20:17.957238  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000013 (ops 60-64)
I20260812 06:20:17.986227  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:17.986958  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd): 462 bytes on disk
I20260812 06:20:17.987455  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.987931  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=5.165500
I20260812 06:20:18.005326  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":6769230,"delete_count":0,"lbm_write_time_us":7172,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:20:18.005898  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:18.017182  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.011s	user 0.006s	sys 0.001s Metrics: {"bytes_written":1436027,"delete_count":0,"lbm_write_time_us":2777,"lbm_writes_lt_1ms":38,"reinsert_count":0,"update_count":175}
I20260812 06:20:18.017823  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:18.204821  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.187s	user 0.133s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836308,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":977,"lbm_read_time_us":13083,"lbm_reads_lt_1ms":670,"lbm_write_time_us":36107,"lbm_writes_lt_1ms":643,"mutex_wait_us":331,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:20:18.205693  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=14.095187
I20260812 06:20:18.267279  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.061s	user 0.023s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29527,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.268078  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:18.286775  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.287292  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:18.458653  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.171s	user 0.124s	sys 0.047s 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":1073,"lbm_read_time_us":11133,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35671,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:20:18.459316  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=14.095187
I20260812 06:20:18.514252  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24305,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.514880  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:18.673188  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.158s	user 0.099s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":225,"lbm_read_time_us":9860,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26509,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:20:18.673918  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=14.095187
I20260812 06:20:18.725171  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.051s	user 0.010s	sys 0.037s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23687,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.725899  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:18.739300  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.013s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.740098  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:18.931064  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.191s	user 0.117s	sys 0.065s 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":162,"lbm_read_time_us":11611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33288,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:18.931741  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=11.118625
I20260812 06:20:18.962198  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.030s	user 0.005s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13388,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.962816  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:18.975095  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4501,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.975783  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:19.097462  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.121s	user 0.092s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":8998,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24453,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.098227  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:19.142393  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.044s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14661,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.143072  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:19.155284  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.156008  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:19.294338  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.138s	user 0.110s	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":157,"lbm_read_time_us":9460,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26504,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.295156  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:19.346635  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.051s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16430,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.347333  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:19.358639  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.359236  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:19.393399  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.034s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1729,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1517,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:19.394294  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd): 447 bytes on disk
I20260812 06:20:19.394827  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.395411  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:19.549527  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.154s	user 0.094s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":841,"lbm_read_time_us":11445,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25801,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:20:19.550479  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd): free 121006441 bytes of WAL
I20260812 06:20:19.550794  4140 log_reader.cc:385] T df43cfbb4d4c44498b3f724a712ac7bd: removed 12 log segments from log reader
I20260812 06:20:19.550884  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000014 (ops 65-69)
I20260812 06:20:19.550954  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000015 (ops 70-74)
I20260812 06:20:19.551008  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000016 (ops 75-79)
I20260812 06:20:19.551060  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000017 (ops 80-84)
I20260812 06:20:19.551115  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000018 (ops 85-89)
I20260812 06:20:19.551165  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000019 (ops 90-94)
I20260812 06:20:19.551219  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000020 (ops 95-99)
I20260812 06:20:19.551271  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000021 (ops 100-104)
I20260812 06:20:19.551326  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000022 (ops 105-108)
I20260812 06:20:19.551386  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000023 (ops 109-113)
I20260812 06:20:19.551440  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000024 (ops 114-118)
I20260812 06:20:19.551496  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000025 (ops 119-123)
I20260812 06:20:19.582363  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:19.582966  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=14.095187
I20260812 06:20:19.634150  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.051s	user 0.043s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22630,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.634891  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:19.655546  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.656107  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:19.864418  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.208s	user 0.149s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":643,"lbm_read_time_us":14324,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35860,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:20:19.865105  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=14.095187
I20260812 06:20:19.920850  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.056s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.921419  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:19.933992  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.934464  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:20.094568  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.160s	user 0.112s	sys 0.047s 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":356,"lbm_read_time_us":11772,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34221,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:20:20.095350  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=11.118625
I20260812 06:20:20.131197  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.036s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15343,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:20.131973  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:20.150429  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6049,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.151037  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:20.289461  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.138s	user 0.090s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1197,"lbm_read_time_us":9537,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28297,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:20:20.290215  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:20.336735  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.046s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15928,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.337247  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:20.348582  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.349555  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:20.484189  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.134s	user 0.102s	sys 0.029s 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":114,"lbm_read_time_us":9504,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27151,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:20:20.484738  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:20.548223  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.063s	user 0.031s	sys 0.017s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17369,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.548880  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:20.566025  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.566720  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:20.710013  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.143s	user 0.093s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":774,"lbm_read_time_us":12883,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23138,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":128384,"update_count":2000}
I20260812 06:20:20.710692  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:20.757269  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.046s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.757884  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:20.769934  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.770677  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:20.913414  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.142s	user 0.117s	sys 0.024s 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":1007,"lbm_read_time_us":10183,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28524,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:20:20.914244  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:20.953452  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.039s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16939,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.954182  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:20.970026  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.970670  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:21.001822  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushMRSOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1428,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1779,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:21.002537  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd): free 124257484 bytes of WAL
I20260812 06:20:21.002786  4140 log_reader.cc:385] T df43cfbb4d4c44498b3f724a712ac7bd: removed 12 log segments from log reader
I20260812 06:20:21.002835  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000026 (ops 124-128)
I20260812 06:20:21.002864  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000027 (ops 129-133)
I20260812 06:20:21.002909  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000028 (ops 134-138)
I20260812 06:20:21.002952  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000029 (ops 139-143)
I20260812 06:20:21.003005  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000030 (ops 144-148)
I20260812 06:20:21.003048  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000031 (ops 149-153)
I20260812 06:20:21.003095  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000032 (ops 154-158)
I20260812 06:20:21.003136  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000033 (ops 159-162)
I20260812 06:20:21.003178  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000034 (ops 163-167)
I20260812 06:20:21.003223  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000035 (ops 168-172)
I20260812 06:20:21.003262  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000036 (ops 173-177)
I20260812 06:20:21.003322  4140 log.cc:1079] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/df43cfbb4d4c44498b3f724a712ac7bd/wal-000000037 (ops 178-182)
I20260812 06:20:21.033159  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: LogGCOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:21.033727  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=6.157687
I20260812 06:20:21.058111  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10390,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:21.058707  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd): 472 bytes on disk
I20260812 06:20:21.060129  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: UndoDeltaBlockGCOp(df43cfbb4d4c44498b3f724a712ac7bd) 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:21.060782  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:21.240253  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.179s	user 0.142s	sys 0.034s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836256,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1336,"lbm_read_time_us":13590,"lbm_reads_lt_1ms":665,"lbm_write_time_us":37807,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:20:21.241326  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=14.095187
I20260812 06:20:21.293066  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.052s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409919,"delete_count":0,"lbm_write_time_us":20704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.293699  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=2.188937
I20260812 06:20:21.307265  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.307979  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:21.432430  4021 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.186s	user 1.930s	sys 0.149s
I20260812 06:20:21.472760  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.165s	user 0.112s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733740,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":12169,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31460,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:20:21.473374  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=10.126437
I20260812 06:20:21.503105  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: FlushDeltaMemStoresOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.030s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12545,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.503940  4209 maintenance_manager.cc:419] P 5b19b32ad3e3411cb135126bbc08f39b: Scheduling MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd): perf score=1.000000
I20260812 06:20:21.519510  4021 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.002s	sys 0.000s
I20260812 06:20:21.520258  4021 tablet_server.cc:179] TabletServer@127.3.237.65:0 shutting down...
I20260812 06:20:21.611433  4140 maintenance_manager.cc:643] P 5b19b32ad3e3411cb135126bbc08f39b: MajorDeltaCompactionOp(df43cfbb4d4c44498b3f724a712ac7bd) complete. Timing: real 0.107s	user 0.072s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":974,"lbm_read_time_us":8332,"lbm_reads_lt_1ms":367,"lbm_write_time_us":21564,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":114,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":1500}
I20260812 06:20:21.612212  4021 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:21.612684  4021 tablet_replica.cc:333] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b: stopping tablet replica
I20260812 06:20:21.612946  4021 raft_consensus.cc:2243] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.613190  4021 raft_consensus.cc:2272] T df43cfbb4d4c44498b3f724a712ac7bd P 5b19b32ad3e3411cb135126bbc08f39b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.629403  4021 tablet_server.cc:196] TabletServer@127.3.237.65:0 shutdown complete.
I20260812 06:20:21.644608  4021 master.cc:562] Master@127.3.237.126:33845 shutting down...
I20260812 06:20:21.648857  4021 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.649125  4021 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.649235  4021 tablet_replica.cc:333] T 00000000000000000000000000000000 P ea44c861f295490b99b6b3617bb91f2f: stopping tablet replica
I20260812 06:20:21.662411  4021 master.cc:584] Master@127.3.237.126:33845 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5852 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:21.764966  4021 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.237.126:43905
I20260812 06:20:21.765422  4021 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:21.768272  4021 server_base.cc:1061] running on GCE node
W20260812 06:20:21.768472  4248 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:21.768497  4243 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:21.768528  4244 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:21.768854  4021 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.768901  4021 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:21.768918  4021 hybrid_clock.cc:648] HybridClock initialized: now 1786515621768917 us; error 0 us; skew 500 ppm
I20260812 06:20:21.769881  4021 webserver.cc:533] Webserver started at http://127.3.237.126:40465/ using document root <none> and password file <none>
I20260812 06:20:21.770033  4021 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.770072  4021 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.770129  4021 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.770519  4021 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/master-0-root/instance:
uuid: "8c5a2079100849ffaec719800fad66ed"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-9zdj"
I20260812 06:20:21.772033  4021 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:21.773131  4253 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:21.773442  4021 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:21.773517  4021 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/master-0-root
uuid: "8c5a2079100849ffaec719800fad66ed"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-9zdj"
I20260812 06:20:21.773643  4021 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-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:21.785605  4021 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.786161  4021 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.790733  4021 rpc_server.cc:307] RPC server started. Bound to: 127.3.237.126:43905
I20260812 06:20:21.792394  4319 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.237.126:43905 every 8 connection(s)
I20260812 06:20:21.793900  4320 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:21.806746  4320 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed: Bootstrap starting.
I20260812 06:20:21.808979  4320 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.810354  4320 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed: No bootstrap required, opened a new log
I20260812 06:20:21.811012  4320 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c5a2079100849ffaec719800fad66ed" member_type: VOTER }
I20260812 06:20:21.811110  4320 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.811132  4320 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c5a2079100849ffaec719800fad66ed, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.811246  4320 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [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: "8c5a2079100849ffaec719800fad66ed" member_type: VOTER }
I20260812 06:20:21.811337  4320 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.811388  4320 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.811450  4320 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.812253  4320 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c5a2079100849ffaec719800fad66ed" member_type: VOTER }
I20260812 06:20:21.812422  4320 leader_election.cc:304] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [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: 8c5a2079100849ffaec719800fad66ed; no voters: 
I20260812 06:20:21.812651  4320 leader_election.cc:290] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.812820  4325 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.813092  4325 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 1 LEADER]: Becoming Leader. State: Replica: 8c5a2079100849ffaec719800fad66ed, State: Running, Role: LEADER
I20260812 06:20:21.813182  4320 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:21.813289  4325 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [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: "8c5a2079100849ffaec719800fad66ed" member_type: VOTER }
I20260812 06:20:21.813913  4327 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8c5a2079100849ffaec719800fad66ed. Latest consensus state: current_term: 1 leader_uuid: "8c5a2079100849ffaec719800fad66ed" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c5a2079100849ffaec719800fad66ed" member_type: VOTER } }
I20260812 06:20:21.814013  4327 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.814119  4326 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8c5a2079100849ffaec719800fad66ed" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c5a2079100849ffaec719800fad66ed" member_type: VOTER } }
I20260812 06:20:21.814236  4326 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.814667  4332 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:21.815614  4332 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:21.815850  4021 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:21.817572  4332 catalog_manager.cc:1383] Generated new cluster ID: a711fc3d74c54842bae880fe27b46e2c
I20260812 06:20:21.817678  4332 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:21.831475  4332 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:21.832216  4332 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:21.841732  4332 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed: Generated new TSK 0
I20260812 06:20:21.841984  4332 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:21.848553  4021 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.850629  4345 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:21.850833  4348 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:21.850910  4346 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:21.850952  4021 server_base.cc:1061] running on GCE node
I20260812 06:20:21.851225  4021 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.851293  4021 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:21.851320  4021 hybrid_clock.cc:648] HybridClock initialized: now 1786515621851319 us; error 0 us; skew 500 ppm
I20260812 06:20:21.852294  4021 webserver.cc:533] Webserver started at http://127.3.237.65:44611/ using document root <none> and password file <none>
I20260812 06:20:21.852530  4021 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.852609  4021 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.852692  4021 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.853122  4021 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/instance:
uuid: "f7e1b4959a2d417da6ba9b96eed13c7d"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-9zdj"
I20260812 06:20:21.854789  4021 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:21.855770  4353 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:21.856034  4021 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:21.856128  4021 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root
uuid: "f7e1b4959a2d417da6ba9b96eed13c7d"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-9zdj"
I20260812 06:20:21.856220  4021 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-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:21.867730  4021 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.868160  4021 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.868510  4021 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:21.869001  4021 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:21.869065  4021 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.869130  4021 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:21.869168  4021 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.873982  4021 rpc_server.cc:307] RPC server started. Bound to: 127.3.237.65:35985
I20260812 06:20:21.874562  4429 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.237.65:35985 every 8 connection(s)
I20260812 06:20:21.884730  4430 heartbeater.cc:344] Connected to a master server at 127.3.237.126:43905
I20260812 06:20:21.884894  4430 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:21.885179  4430 heartbeater.cc:507] Master 127.3.237.126:43905 requested a full tablet report, sending...
I20260812 06:20:21.886026  4274 ts_manager.cc:194] Registered new tserver with Master: f7e1b4959a2d417da6ba9b96eed13c7d (127.3.237.65:35985)
I20260812 06:20:21.886802  4274 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41780
I20260812 06:20:21.886931  4021 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012190045s
I20260812 06:20:21.894547  4274 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41786:
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:21.904317  4386 tablet_service.cc:1511] Processing CreateTablet for tablet 8f021426c03249bbb7d62d8c0b9fc29d (DEFAULT_TABLE table=heavy-update-compaction-test [id=cb970db489074ee391f844d0b82da615]), partition=
I20260812 06:20:21.904628  4386 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8f021426c03249bbb7d62d8c0b9fc29d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:21.906863  4444 tablet_bootstrap.cc:492] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Bootstrap starting.
I20260812 06:20:21.907887  4444 tablet_bootstrap.cc:654] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.909320  4444 tablet_bootstrap.cc:492] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: No bootstrap required, opened a new log
I20260812 06:20:21.909474  4444 ts_tablet_manager.cc:1403] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:21.910055  4444 raft_consensus.cc:359] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f7e1b4959a2d417da6ba9b96eed13c7d" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 35985 } }
I20260812 06:20:21.910152  4444 raft_consensus.cc:385] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.910174  4444 raft_consensus.cc:740] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f7e1b4959a2d417da6ba9b96eed13c7d, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.910346  4444 consensus_queue.cc:260] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [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: "f7e1b4959a2d417da6ba9b96eed13c7d" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 35985 } }
I20260812 06:20:21.910431  4444 raft_consensus.cc:399] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.910456  4444 raft_consensus.cc:493] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.910509  4444 raft_consensus.cc:3060] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.911311  4444 raft_consensus.cc:515] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f7e1b4959a2d417da6ba9b96eed13c7d" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 35985 } }
I20260812 06:20:21.911474  4444 leader_election.cc:304] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [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: f7e1b4959a2d417da6ba9b96eed13c7d; no voters: 
I20260812 06:20:21.911741  4444 leader_election.cc:290] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.911913  4446 raft_consensus.cc:2804] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.912129  4444 ts_tablet_manager.cc:1434] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:21.912153  4430 heartbeater.cc:499] Master 127.3.237.126:43905 was elected leader, sending a full tablet report...
I20260812 06:20:21.912237  4446 raft_consensus.cc:697] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 1 LEADER]: Becoming Leader. State: Replica: f7e1b4959a2d417da6ba9b96eed13c7d, State: Running, Role: LEADER
I20260812 06:20:21.912418  4446 consensus_queue.cc:237] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [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: "f7e1b4959a2d417da6ba9b96eed13c7d" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 35985 } }
I20260812 06:20:21.913976  4272 catalog_manager.cc:5719] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d reported cstate change: term changed from 0 to 1, leader changed from <none> to f7e1b4959a2d417da6ba9b96eed13c7d (127.3.237.65). New cstate: current_term: 1 leader_uuid: "f7e1b4959a2d417da6ba9b96eed13c7d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f7e1b4959a2d417da6ba9b96eed13c7d" member_type: VOTER last_known_addr { host: "127.3.237.65" port: 35985 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:21.977855  4021 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.011s	sys 0.012s
I20260812 06:20:22.125211  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=19.054940
I20260812 06:20:22.289999  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.164s	user 0.127s	sys 0.031s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":834,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39411,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:22.290676  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d): free 20743880 bytes of WAL
I20260812 06:20:22.290954  4359 log_reader.cc:385] T 8f021426c03249bbb7d62d8c0b9fc29d: removed 2 log segments from log reader
I20260812 06:20:22.290999  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000001 (ops 1-6)
I20260812 06:20:22.291031  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000002 (ops 7-11)
I20260812 06:20:22.295557  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:22.295990  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:22.314277  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.315008  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d): 16411393 bytes on disk
I20260812 06:20:22.315587  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.316095  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:22.468148  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.152s	user 0.134s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":541,"lbm_read_time_us":11368,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25906,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":338,"threads_started":5,"update_count":2000}
I20260812 06:20:22.468729  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=11.118625
I20260812 06:20:22.511291  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.042s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18688,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:22.511829  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:22.523584  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.524304  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:22.667634  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.143s	user 0.119s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":10937,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27641,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:20:22.668356  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=10.126437
I20260812 06:20:22.717337  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.049s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15421,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.717900  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:22.730943  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.731693  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:22.896721  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.165s	user 0.087s	sys 0.077s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":12252,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26627,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:20:22.897372  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=10.126437
I20260812 06:20:22.934171  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.037s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13877,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.934806  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:22.947139  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.947768  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:23.085245  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.137s	user 0.113s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":872,"lbm_read_time_us":10217,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27394,"lbm_writes_lt_1ms":443,"mutex_wait_us":306,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:20:23.085882  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=10.126437
I20260812 06:20:23.132586  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.046s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15013,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.133126  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:23.144773  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.145376  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:23.271947  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.126s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1414,"lbm_read_time_us":8249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26235,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:20:23.272729  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=10.126437
I20260812 06:20:23.334496  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.062s	user 0.017s	sys 0.034s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17784,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.335143  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:23.347366  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.347905  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:23.507735  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.160s	user 0.103s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":11327,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26191,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:20:23.508396  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=10.126437
I20260812 06:20:23.555266  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.047s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.555819  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:23.568334  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.569069  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:23.596472  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.027s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":211,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1848,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1483,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:23.597172  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d): free 112239310 bytes of WAL
I20260812 06:20:23.597457  4359 log_reader.cc:385] T 8f021426c03249bbb7d62d8c0b9fc29d: removed 11 log segments from log reader
I20260812 06:20:23.597506  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000003 (ops 12-16)
I20260812 06:20:23.597539  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000004 (ops 17-21)
I20260812 06:20:23.597604  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000005 (ops 22-26)
I20260812 06:20:23.597673  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000006 (ops 27-31)
I20260812 06:20:23.597756  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000007 (ops 32-36)
I20260812 06:20:23.597795  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000008 (ops 37-40)
I20260812 06:20:23.597838  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000009 (ops 41-45)
I20260812 06:20:23.597877  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000010 (ops 46-50)
I20260812 06:20:23.597914  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000011 (ops 51-55)
I20260812 06:20:23.597957  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000012 (ops 56-60)
I20260812 06:20:23.597995  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000013 (ops 61-65)
I20260812 06:20:23.625428  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:23.625942  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d): 448 bytes on disk
I20260812 06:20:23.626498  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.627048  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=3.181125
I20260812 06:20:23.655591  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7633,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:23.656177  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:23.667388  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.667982  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:23.888899  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.221s	user 0.149s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":335,"lbm_read_time_us":16381,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36765,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:20:23.889539  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:23.955966  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.066s	user 0.026s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23738,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.956604  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:23.968138  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.968683  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:24.157998  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.189s	user 0.121s	sys 0.064s 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":436,"lbm_read_time_us":14367,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30322,"lbm_writes_lt_1ms":543,"mutex_wait_us":161,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:20:24.158707  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=11.118625
I20260812 06:20:24.227682  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.069s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":41736,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.228211  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=6.157687
I20260812 06:20:24.264166  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.036s	user 0.008s	sys 0.023s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9106,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:20:24.264879  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:24.457136  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.192s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":47,"lbm_read_time_us":14085,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32181,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2500}
I20260812 06:20:24.457957  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:24.522176  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.064s	user 0.034s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29729,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.522799  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:24.551626  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.029s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.552388  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:24.564602  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.565291  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:24.787005  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.221s	user 0.148s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":926,"lbm_read_time_us":16425,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37042,"lbm_writes_lt_1ms":643,"mutex_wait_us":312,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":3000}
I20260812 06:20:24.787662  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:24.854997  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.067s	user 0.033s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18989,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.855722  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:24.867430  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.867903  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:25.065771  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.198s	user 0.143s	sys 0.044s 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":743,"lbm_read_time_us":13697,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30887,"lbm_writes_lt_1ms":543,"mutex_wait_us":343,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:20:25.066306  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:25.127575  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.061s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25687,"lbm_writes_lt_1ms":403,"mutex_wait_us":66,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.128089  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:25.149288  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.021s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.150151  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:25.187933  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.038s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":321,"dirs.run_wall_time_us":1524,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1653,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:25.188810  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d): free 120553331 bytes of WAL
I20260812 06:20:25.189087  4359 log_reader.cc:385] T 8f021426c03249bbb7d62d8c0b9fc29d: removed 12 log segments from log reader
I20260812 06:20:25.189294  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000014 (ops 66-70)
I20260812 06:20:25.189386  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000015 (ops 71-74)
I20260812 06:20:25.189435  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000016 (ops 75-79)
I20260812 06:20:25.189482  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000017 (ops 80-84)
I20260812 06:20:25.189528  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000018 (ops 85-89)
I20260812 06:20:25.189572  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000019 (ops 90-94)
I20260812 06:20:25.189649  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000020 (ops 95-99)
I20260812 06:20:25.189706  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000021 (ops 100-104)
I20260812 06:20:25.189738  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000022 (ops 105-109)
I20260812 06:20:25.189805  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000023 (ops 110-114)
I20260812 06:20:25.189850  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000024 (ops 115-118)
I20260812 06:20:25.189895  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000025 (ops 119-123)
I20260812 06:20:25.220362  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:20:25.220876  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d): 447 bytes on disk
I20260812 06:20:25.221403  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.222136  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=3.181125
I20260812 06:20:25.240862  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.019s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5343,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.241321  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:25.251689  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.252218  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:25.514997  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.263s	user 0.173s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":787,"lbm_read_time_us":18508,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42131,"lbm_writes_lt_1ms":743,"mutex_wait_us":40,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":100224,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:20:25.516481  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=18.063937
I20260812 06:20:25.579077  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.062s	user 0.031s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25839,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:25.579743  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:25.751965  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.172s	user 0.109s	sys 0.063s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":456,"lbm_read_time_us":13486,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27276,"lbm_writes_lt_1ms":543,"mutex_wait_us":115,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:20:25.752692  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:25.815306  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.062s	user 0.029s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.815960  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:25.828595  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.829569  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:26.031804  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.202s	user 0.147s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":14126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34468,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:20:26.032521  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:26.094962  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.062s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23426,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.095588  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:26.118561  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.119161  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:26.298492  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.179s	user 0.107s	sys 0.064s 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":335,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27900,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.299254  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:26.354696  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23354,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.355229  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:26.366640  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.367378  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:26.558167  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.191s	user 0.121s	sys 0.053s 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":153,"lbm_read_time_us":11780,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31035,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:20:26.558996  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:26.616815  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.058s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25129,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.617419  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:26.628413  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.629149  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:26.785313  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.156s	user 0.102s	sys 0.053s 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":1739,"lbm_read_time_us":11601,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32711,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:20:26.786305  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=11.118625
I20260812 06:20:26.830818  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12594660,"delete_count":0,"lbm_write_time_us":19462,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1535}
I20260812 06:20:26.831467  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:26.844965  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5083,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:20:26.845693  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:26.877038  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushMRSOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.031s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1561,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1465,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:26.877832  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d): free 124710539 bytes of WAL
I20260812 06:20:26.878082  4359 log_reader.cc:385] T 8f021426c03249bbb7d62d8c0b9fc29d: removed 12 log segments from log reader
I20260812 06:20:26.878127  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000026 (ops 124-128)
I20260812 06:20:26.878157  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000027 (ops 129-133)
I20260812 06:20:26.878229  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000028 (ops 134-138)
I20260812 06:20:26.878283  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000029 (ops 139-143)
I20260812 06:20:26.878325  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000030 (ops 144-148)
I20260812 06:20:26.878373  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000031 (ops 149-153)
I20260812 06:20:26.878410  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000032 (ops 154-158)
I20260812 06:20:26.878449  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000033 (ops 159-163)
I20260812 06:20:26.878491  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000034 (ops 164-168)
I20260812 06:20:26.878530  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000035 (ops 169-173)
I20260812 06:20:26.878569  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000036 (ops 174-178)
I20260812 06:20:26.878608  4359 log.cc:1079] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: Deleting log segment in path: /tmp/dist-test-taskmnIzdD/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615901568-4021-0/minicluster-data/ts-0-root/wals/8f021426c03249bbb7d62d8c0b9fc29d/wal-000000037 (ops 179-183)
I20260812 06:20:26.907241  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: LogGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:26.907693  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=3.181125
I20260812 06:20:26.924468  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.017s	user 0.001s	sys 0.013s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":6594,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:20:26.925124  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d): 483 bytes on disk
I20260812 06:20:26.925820  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: UndoDeltaBlockGCOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.926501  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.196750
I20260812 06:20:26.940038  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4861,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:26.940626  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:27.133320  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.193s	user 0.142s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877307,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":739,"lbm_read_time_us":12952,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38216,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:20:27.134114  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=14.095187
I20260812 06:20:27.192058  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.058s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.192651  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=2.188937
I20260812 06:20:27.204823  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.205411  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=1.000000
I20260812 06:20:27.303311  4021 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.325s	user 1.930s	sys 0.223s
I20260812 06:20:27.382097  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: MajorDeltaCompactionOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.176s	user 0.125s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":359,"lbm_read_time_us":13014,"lbm_reads_lt_1ms":568,"lbm_write_time_us":35767,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25984,"update_count":2500}
I20260812 06:20:27.383060  4432 maintenance_manager.cc:419] P f7e1b4959a2d417da6ba9b96eed13c7d: Scheduling FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d): perf score=6.157687
I20260812 06:20:27.386147  4021 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.003s	sys 0.000s
I20260812 06:20:27.386715  4021 tablet_server.cc:179] TabletServer@127.3.237.65:0 shutting down...
I20260812 06:20:27.410086  4359 maintenance_manager.cc:643] P f7e1b4959a2d417da6ba9b96eed13c7d: FlushDeltaMemStoresOp(8f021426c03249bbb7d62d8c0b9fc29d) complete. Timing: real 0.027s	user 0.014s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11495,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:27.410790  4021 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:27.411141  4021 tablet_replica.cc:333] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d: stopping tablet replica
I20260812 06:20:27.411428  4021 raft_consensus.cc:2243] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.411640  4021 raft_consensus.cc:2272] T 8f021426c03249bbb7d62d8c0b9fc29d P f7e1b4959a2d417da6ba9b96eed13c7d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.426740  4021 tablet_server.cc:196] TabletServer@127.3.237.65:0 shutdown complete.
I20260812 06:20:27.430668  4021 master.cc:562] Master@127.3.237.126:43905 shutting down...
I20260812 06:20:27.434262  4021 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.434489  4021 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.434597  4021 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8c5a2079100849ffaec719800fad66ed: stopping tablet replica
I20260812 06:20:27.447284  4021 master.cc:584] Master@127.3.237.126:43905 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5779 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11632 ms total)

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