[==========] 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:09.331194 14936 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.150.62:46789
I20260812 06:20:09.332296 14936 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:09.332861 14936 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:09.339525 14941 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:09.339569 14936 server_base.cc:1061] running on GCE node
W20260812 06:20:09.339486 14942 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:09.339874 14944 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:09.340422 14936 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:09.340515 14936 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:09.340548 14936 hybrid_clock.cc:648] HybridClock initialized: now 1786515609340546 us; error 0 us; skew 500 ppm
I20260812 06:20:09.342419 14936 webserver.cc:533] Webserver started at http://127.14.150.62:32929/ using document root <none> and password file <none>
I20260812 06:20:09.342955 14936 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:09.343016 14936 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:09.343209 14936 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:09.344988 14936 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/master-0-root/instance:
uuid: "94793b9af8c54675832b24c753c8f1fd"
format_stamp: "Formatted at 2026-08-12 06:20:09 on dist-test-slave-bxbt"
I20260812 06:20:09.348829 14936 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:20:09.351086 14949 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:09.352299 14936 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:20:09.352408 14936 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/master-0-root
uuid: "94793b9af8c54675832b24c753c8f1fd"
format_stamp: "Formatted at 2026-08-12 06:20:09 on dist-test-slave-bxbt"
I20260812 06:20:09.352491 14936 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-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:09.391527 14936 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:09.392316 14936 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:09.392535 14936 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:09.400458 14936 rpc_server.cc:307] RPC server started. Bound to: 127.14.150.62:46789
I20260812 06:20:09.400460 15001 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.150.62:46789 every 8 connection(s)
I20260812 06:20:09.402858 15002 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:09.408550 15002 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: Bootstrap starting.
I20260812 06:20:09.410935 15002 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:09.411962 15002 log.cc:826] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:09.413764 15002 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: No bootstrap required, opened a new log
I20260812 06:20:09.416657 15002 raft_consensus.cc:359] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94793b9af8c54675832b24c753c8f1fd" member_type: VOTER }
I20260812 06:20:09.416831 15002 raft_consensus.cc:385] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:09.416950 15002 raft_consensus.cc:740] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 94793b9af8c54675832b24c753c8f1fd, State: Initialized, Role: FOLLOWER
I20260812 06:20:09.417577 15002 consensus_queue.cc:260] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [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: "94793b9af8c54675832b24c753c8f1fd" member_type: VOTER }
I20260812 06:20:09.417757 15002 raft_consensus.cc:399] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:09.417832 15002 raft_consensus.cc:493] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:09.418010 15002 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:09.418857 15002 raft_consensus.cc:515] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94793b9af8c54675832b24c753c8f1fd" member_type: VOTER }
I20260812 06:20:09.419322 15002 leader_election.cc:304] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [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: 94793b9af8c54675832b24c753c8f1fd; no voters: 
I20260812 06:20:09.419701 15002 leader_election.cc:290] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:09.419883 15005 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:09.420159 15005 raft_consensus.cc:697] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 1 LEADER]: Becoming Leader. State: Replica: 94793b9af8c54675832b24c753c8f1fd, State: Running, Role: LEADER
I20260812 06:20:09.420579 15005 consensus_queue.cc:237] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [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: "94793b9af8c54675832b24c753c8f1fd" member_type: VOTER }
I20260812 06:20:09.420837 15002 sys_catalog.cc:565] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:09.422556 15007 sys_catalog.cc:455] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 94793b9af8c54675832b24c753c8f1fd. Latest consensus state: current_term: 1 leader_uuid: "94793b9af8c54675832b24c753c8f1fd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94793b9af8c54675832b24c753c8f1fd" member_type: VOTER } }
I20260812 06:20:09.422605 15006 sys_catalog.cc:455] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "94793b9af8c54675832b24c753c8f1fd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94793b9af8c54675832b24c753c8f1fd" member_type: VOTER } }
I20260812 06:20:09.422688 15007 sys_catalog.cc:458] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:09.422701 15006 sys_catalog.cc:458] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:09.423403 14936 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:09.425611 15020 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:09.425704 15020 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:09.425792 15016 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:09.426529 15016 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:09.431578 15016 catalog_manager.cc:1383] Generated new cluster ID: 7007cab53c2240bba3918cd09411e3fa
I20260812 06:20:09.431656 15016 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:09.444262 15016 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:09.445568 15016 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:09.456817 15016 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: Generated new TSK 0
I20260812 06:20:09.457777 15016 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:09.488971 14936 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:09.492164 15027 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:09.492195 15025 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:09.492430 14936 server_base.cc:1061] running on GCE node
W20260812 06:20:09.492337 15024 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:09.492748 14936 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:09.492820 14936 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:09.492847 14936 hybrid_clock.cc:648] HybridClock initialized: now 1786515609492847 us; error 0 us; skew 500 ppm
I20260812 06:20:09.493767 14936 webserver.cc:533] Webserver started at http://127.14.150.1:44383/ using document root <none> and password file <none>
I20260812 06:20:09.493963 14936 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:09.494042 14936 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:09.494124 14936 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:09.494562 14936 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/instance:
uuid: "fc7246ffdd944dc59679ab641b770bcc"
format_stamp: "Formatted at 2026-08-12 06:20:09 on dist-test-slave-bxbt"
I20260812 06:20:09.496225 14936 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:09.497272 15032 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:09.497540 14936 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:09.497615 14936 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root
uuid: "fc7246ffdd944dc59679ab641b770bcc"
format_stamp: "Formatted at 2026-08-12 06:20:09 on dist-test-slave-bxbt"
I20260812 06:20:09.497704 14936 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-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:09.518749 14936 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:09.519553 14936 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:09.520164 14936 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:09.521050 14936 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:09.521106 14936 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:09.521174 14936 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:09.521220 14936 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:09.528486 14936 rpc_server.cc:307] RPC server started. Bound to: 127.14.150.1:42375
I20260812 06:20:09.528519 15095 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.150.1:42375 every 8 connection(s)
I20260812 06:20:09.542486 15096 heartbeater.cc:344] Connected to a master server at 127.14.150.62:46789
I20260812 06:20:09.542790 15096 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:09.543306 15096 heartbeater.cc:507] Master 127.14.150.62:46789 requested a full tablet report, sending...
I20260812 06:20:09.544970 14966 ts_manager.cc:194] Registered new tserver with Master: fc7246ffdd944dc59679ab641b770bcc (127.14.150.1:42375)
I20260812 06:20:09.545121 14936 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015933138s
I20260812 06:20:09.546545 14966 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42292
I20260812 06:20:09.555804 14966 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42306:
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:09.571053 15060 tablet_service.cc:1511] Processing CreateTablet for tablet b95287e5fc8b4c9fa86b59ba7b6e3c4a (DEFAULT_TABLE table=heavy-update-compaction-test [id=01685959a4224eb98bde032031da68fa]), partition=
I20260812 06:20:09.571568 15060 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b95287e5fc8b4c9fa86b59ba7b6e3c4a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:09.574076 15108 tablet_bootstrap.cc:492] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Bootstrap starting.
I20260812 06:20:09.575439 15108 tablet_bootstrap.cc:654] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:09.576812 15108 tablet_bootstrap.cc:492] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: No bootstrap required, opened a new log
I20260812 06:20:09.576952 15108 ts_tablet_manager.cc:1403] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:09.577445 15108 raft_consensus.cc:359] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fc7246ffdd944dc59679ab641b770bcc" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 42375 } }
I20260812 06:20:09.577584 15108 raft_consensus.cc:385] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:09.577657 15108 raft_consensus.cc:740] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fc7246ffdd944dc59679ab641b770bcc, State: Initialized, Role: FOLLOWER
I20260812 06:20:09.577836 15108 consensus_queue.cc:260] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [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: "fc7246ffdd944dc59679ab641b770bcc" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 42375 } }
I20260812 06:20:09.577973 15108 raft_consensus.cc:399] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:09.578035 15108 raft_consensus.cc:493] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:09.578080 15108 raft_consensus.cc:3060] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:09.579078 15108 raft_consensus.cc:515] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fc7246ffdd944dc59679ab641b770bcc" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 42375 } }
I20260812 06:20:09.579239 15108 leader_election.cc:304] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [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: fc7246ffdd944dc59679ab641b770bcc; no voters: 
I20260812 06:20:09.579473 15108 leader_election.cc:290] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:09.579609 15110 raft_consensus.cc:2804] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:09.579900 15108 ts_tablet_manager.cc:1434] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:09.579928 15110 raft_consensus.cc:697] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 1 LEADER]: Becoming Leader. State: Replica: fc7246ffdd944dc59679ab641b770bcc, State: Running, Role: LEADER
I20260812 06:20:09.580111 15096 heartbeater.cc:499] Master 127.14.150.62:46789 was elected leader, sending a full tablet report...
I20260812 06:20:09.580114 15110 consensus_queue.cc:237] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [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: "fc7246ffdd944dc59679ab641b770bcc" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 42375 } }
I20260812 06:20:09.583303 14966 catalog_manager.cc:5719] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc reported cstate change: term changed from 0 to 1, leader changed from <none> to fc7246ffdd944dc59679ab641b770bcc (127.14.150.1). New cstate: current_term: 1 leader_uuid: "fc7246ffdd944dc59679ab641b770bcc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fc7246ffdd944dc59679ab641b770bcc" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 42375 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:09.644609 14936 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.020s	sys 0.004s
I20260812 06:20:09.779721 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=19.054940
I20260812 06:20:09.969338 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.189s	user 0.129s	sys 0.052s Metrics: {"bytes_written":12840810,"cfile_init":1,"compiler_manager_pool.queue_time_us":251,"delete_count":0,"dirs.queue_time_us":1715,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":757,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48903,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":769,"mutex_wait_us":193,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":294144,"thread_start_us":164,"threads_started":1,"update_count":1565}
I20260812 06:20:09.970444 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): free 20290830 bytes of WAL
I20260812 06:20:09.970767 15037 log_reader.cc:385] T b95287e5fc8b4c9fa86b59ba7b6e3c4a: removed 2 log segments from log reader
I20260812 06:20:09.970844 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000001 (ops 1-6)
I20260812 06:20:09.970919 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000002 (ops 7-10)
I20260812 06:20:09.974709 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:09.975114 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=3.181125
I20260812 06:20:09.993610 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.018s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4759047,"delete_count":0,"lbm_write_time_us":5091,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 06:20:09.994134 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): 16411394 bytes on disk
I20260812 06:20:09.994765 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.995184 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.196750
I20260812 06:20:10.003901 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":2996,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:20:10.004415 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:10.186290 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.182s	user 0.134s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774787,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":852,"lbm_read_time_us":11959,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28603,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":333,"threads_started":5,"update_count":2500}
I20260812 06:20:10.186929 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:10.229812 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.043s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14381,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.230361 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:10.245200 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.245887 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:10.370428 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.124s	user 0.114s	sys 0.009s 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":362,"lbm_read_time_us":9335,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22717,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.371003 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:10.414481 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.043s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19228,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.414970 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:10.427506 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4594,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.428208 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:10.553751 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.125s	user 0.088s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1069,"lbm_read_time_us":9213,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23769,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:20:10.554255 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:10.607290 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.053s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17843,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.607908 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:10.623483 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.624140 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:10.749111 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.125s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1128,"lbm_read_time_us":8610,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22742,"lbm_writes_lt_1ms":443,"mutex_wait_us":347,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:20:10.749699 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:10.787366 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.037s	user 0.023s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12868,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.788004 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:10.798806 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.799321 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:10.947525 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.148s	user 0.081s	sys 0.060s 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":564,"lbm_read_time_us":11803,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21375,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2000}
I20260812 06:20:10.948304 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:10.995436 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.047s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14169,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.995965 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:11.007854 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.008559 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:11.133507 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.125s	user 0.084s	sys 0.040s 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":687,"lbm_read_time_us":8499,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24892,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:20:11.134099 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:11.174517 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.040s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13602,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:11.175010 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:11.186102 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.186851 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:11.219758 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1395,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1766,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:11.220521 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): free 112692328 bytes of WAL
I20260812 06:20:11.220747 15037 log_reader.cc:385] T b95287e5fc8b4c9fa86b59ba7b6e3c4a: removed 11 log segments from log reader
I20260812 06:20:11.220814 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000003 (ops 11-15)
I20260812 06:20:11.220871 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000004 (ops 16-20)
I20260812 06:20:11.220911 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000005 (ops 21-25)
I20260812 06:20:11.220948 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000006 (ops 26-30)
I20260812 06:20:11.220984 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000007 (ops 31-35)
I20260812 06:20:11.221021 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000008 (ops 36-40)
I20260812 06:20:11.221058 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000009 (ops 41-45)
I20260812 06:20:11.221093 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000010 (ops 46-50)
I20260812 06:20:11.221129 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000011 (ops 51-55)
I20260812 06:20:11.221166 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000012 (ops 56-60)
I20260812 06:20:11.221202 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000013 (ops 61-65)
I20260812 06:20:11.242486 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:20:11.243021 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=3.181125
I20260812 06:20:11.256814 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:20:11.257242 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): free 12017983 bytes of WAL
I20260812 06:20:11.257457 15037 log_reader.cc:385] T b95287e5fc8b4c9fa86b59ba7b6e3c4a: removed 1 log segments from log reader
I20260812 06:20:11.257503 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000014 (ops 66-70)
I20260812 06:20:11.259649 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:11.260015 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:11.270875 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3774458,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:20:11.271371 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): 463 bytes on disk
I20260812 06:20:11.271957 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":152,"lbm_reads_lt_1ms":4}
I20260812 06:20:11.272433 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:11.456540 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.184s	user 0.152s	sys 0.027s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":646,"lbm_read_time_us":12718,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37402,"lbm_writes_lt_1ms":643,"mutex_wait_us":139,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:20:11.457295 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=14.095187
I20260812 06:20:11.513056 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.056s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22988,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.513564 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:11.527128 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.527648 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:11.690884 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.163s	user 0.129s	sys 0.032s 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":416,"lbm_read_time_us":12579,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30419,"lbm_writes_lt_1ms":543,"mutex_wait_us":101,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:11.691589 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=12.110812
I20260812 06:20:11.727499 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.036s	user 0.027s	sys 0.005s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":14860,"lbm_writes_lt_1ms":335,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":1660}
I20260812 06:20:11.728056 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.196750
I20260812 06:20:11.740660 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.012s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3517,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:20:11.741132 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:11.884706 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.143s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672248,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":908,"lbm_read_time_us":8594,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25376,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.885327 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=11.118625
I20260812 06:20:11.925637 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17245,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:11.926163 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:11.938377 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.938978 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:12.073035 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.134s	user 0.084s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":7315,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26088,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:20:12.073773 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:12.104755 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13286,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.105265 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:12.123044 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.123555 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:12.251047 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.127s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":643,"lbm_read_time_us":7111,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25485,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:20:12.251821 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:12.292769 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.041s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14368,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.293334 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:12.304152 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.304646 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:12.444416 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.140s	user 0.115s	sys 0.024s 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":159,"lbm_read_time_us":9429,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26319,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:12.445173 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:12.496726 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.051s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14460,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.497368 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:12.510360 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.510855 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:12.656795 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.146s	user 0.093s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":934,"lbm_read_time_us":10930,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22383,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:20:12.657586 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:12.695602 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.038s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15220,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.696161 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:12.712821 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.016s	user 0.014s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.713517 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:12.742518 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1326,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1541,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:12.743261 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): free 121459510 bytes of WAL
I20260812 06:20:12.743523 15037 log_reader.cc:385] T b95287e5fc8b4c9fa86b59ba7b6e3c4a: removed 12 log segments from log reader
I20260812 06:20:12.743571 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000015 (ops 71-75)
I20260812 06:20:12.743602 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000016 (ops 76-80)
I20260812 06:20:12.743659 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000017 (ops 81-85)
I20260812 06:20:12.743731 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000018 (ops 86-90)
I20260812 06:20:12.743773 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000019 (ops 91-95)
I20260812 06:20:12.743817 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000020 (ops 96-100)
I20260812 06:20:12.743855 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000021 (ops 101-105)
I20260812 06:20:12.743942 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000022 (ops 106-110)
I20260812 06:20:12.743960 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000023 (ops 111-115)
I20260812 06:20:12.744017 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000024 (ops 116-120)
I20260812 06:20:12.744056 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000025 (ops 121-125)
I20260812 06:20:12.744095 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000026 (ops 126-130)
I20260812 06:20:12.768893 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:12.769395 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=4.173312
I20260812 06:20:12.791477 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.022s	user 0.010s	sys 0.008s Metrics: {"bytes_written":5579537,"delete_count":0,"lbm_write_time_us":5699,"lbm_writes_lt_1ms":139,"reinsert_count":0,"update_count":680}
I20260812 06:20:12.792074 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): 481 bytes on disk
I20260812 06:20:12.792548 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.793067 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.196750
I20260812 06:20:12.800990 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":2638,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:20:12.801647 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:13.002084 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.200s	user 0.148s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877306,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":284,"lbm_read_time_us":14775,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32867,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:13.002645 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=14.095187
I20260812 06:20:13.059777 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.057s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20943,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.060434 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:13.074467 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6566,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.074954 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:13.249018 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.174s	user 0.100s	sys 0.071s 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":220,"lbm_read_time_us":12083,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28865,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:13.249622 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=11.118625
I20260812 06:20:13.285198 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.035s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14917,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:13.286201 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:13.303380 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5300,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.303929 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:13.442840 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.139s	user 0.106s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":993,"lbm_read_time_us":8136,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25411,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:13.443492 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=11.118625
I20260812 06:20:13.479173 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.035s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16039,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:13.479830 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:13.496366 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.016s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4497,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.497041 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:13.629666 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.132s	user 0.101s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":788,"lbm_read_time_us":7709,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25283,"lbm_writes_lt_1ms":443,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:13.630191 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=11.118625
I20260812 06:20:13.672546 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.042s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15141,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:13.673064 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:13.696228 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.023s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3810,"lbm_writes_lt_1ms":93,"mutex_wait_us":45,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.696796 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:13.712019 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.712718 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:13.873713 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.161s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":921,"lbm_read_time_us":12023,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30780,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:20:13.874889 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=11.118625
I20260812 06:20:13.919734 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.043s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17234,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:13.920360 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:13.934752 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5209,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.935402 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:14.075551 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.140s	user 0.092s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":9981,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23917,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:14.076479 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=10.126437
I20260812 06:20:14.119413 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.043s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17263,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.120086 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:14.143451 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.144019 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:14.214327 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushMRSOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.070s	user 0.041s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2438,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:14.215139 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): 463 bytes on disk
I20260812 06:20:14.215646 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: UndoDeltaBlockGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:20:14.216269 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=3.181125
I20260812 06:20:14.230453 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.014s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:14.230949 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): free 124257456 bytes of WAL
I20260812 06:20:14.231175 15037 log_reader.cc:385] T b95287e5fc8b4c9fa86b59ba7b6e3c4a: removed 12 log segments from log reader
I20260812 06:20:14.231236 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000027 (ops 131-135)
I20260812 06:20:14.231316 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000028 (ops 136-140)
I20260812 06:20:14.231357 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000029 (ops 141-145)
I20260812 06:20:14.231385 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000030 (ops 146-150)
I20260812 06:20:14.231421 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000031 (ops 151-154)
I20260812 06:20:14.231459 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000032 (ops 155-159)
I20260812 06:20:14.231499 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000033 (ops 160-164)
I20260812 06:20:14.231539 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000034 (ops 165-169)
I20260812 06:20:14.231582 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000035 (ops 170-174)
I20260812 06:20:14.231623 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000036 (ops 175-179)
I20260812 06:20:14.231663 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000037 (ops 180-184)
I20260812 06:20:14.231734 15037 log.cc:1079] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/b95287e5fc8b4c9fa86b59ba7b6e3c4a/wal-000000038 (ops 185-189)
I20260812 06:20:14.255411 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: LogGCOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:14.255905 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:14.277856 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5566,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:14.278322 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=2.188937
I20260812 06:20:14.289255 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.289757 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:14.521258 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.231s	user 0.154s	sys 0.073s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":567,"lbm_read_time_us":14165,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38089,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:20:14.523655 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=16.079562
I20260812 06:20:14.532809 14936 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.888s	user 1.820s	sys 0.130s
I20260812 06:20:14.565186 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.041s	user 0.020s	sys 0.020s Metrics: {"bytes_written":17886768,"delete_count":0,"lbm_write_time_us":18515,"lbm_writes_lt_1ms":439,"reinsert_count":0,"update_count":2180}
I20260812 06:20:14.565855 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.196750
I20260812 06:20:14.574618 14936 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.041s	user 0.001s	sys 0.000s
I20260812 06:20:14.575297 14936 tablet_server.cc:179] TabletServer@127.14.150.1:0 shutting down...
I20260812 06:20:14.577297 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: FlushDeltaMemStoresOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":3594,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:20:14.577993 15097 maintenance_manager.cc:419] P fc7246ffdd944dc59679ab641b770bcc: Scheduling MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a): perf score=1.000000
I20260812 06:20:14.714943 15037 maintenance_manager.cc:643] P fc7246ffdd944dc59679ab641b770bcc: MajorDeltaCompactionOp(b95287e5fc8b4c9fa86b59ba7b6e3c4a) complete. Timing: real 0.137s	user 0.112s	sys 0.024s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512260,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":972,"lbm_read_time_us":8167,"lbm_reads_lt_1ms":518,"lbm_write_time_us":23672,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":43648,"update_count":2500}
I20260812 06:20:14.715765 14936 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:14.716444 14936 tablet_replica.cc:333] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc: stopping tablet replica
I20260812 06:20:14.716699 14936 raft_consensus.cc:2243] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:14.716945 14936 raft_consensus.cc:2272] T b95287e5fc8b4c9fa86b59ba7b6e3c4a P fc7246ffdd944dc59679ab641b770bcc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:14.732558 14936 tablet_server.cc:196] TabletServer@127.14.150.1:0 shutdown complete.
I20260812 06:20:14.761070 14936 master.cc:562] Master@127.14.150.62:46789 shutting down...
I20260812 06:20:14.764880 14936 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:14.765076 14936 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:14.765132 14936 tablet_replica.cc:333] T 00000000000000000000000000000000 P 94793b9af8c54675832b24c753c8f1fd: stopping tablet replica
I20260812 06:20:14.777709 14936 master.cc:584] Master@127.14.150.62:46789 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5538 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:14.869087 14936 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.150.62:39077
I20260812 06:20:14.869513 14936 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:14.871802 15127 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:14.871814 15130 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:14.871915 15128 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:14.871958 14936 server_base.cc:1061] running on GCE node
I20260812 06:20:14.872293 14936 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:14.872342 14936 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:14.872357 14936 hybrid_clock.cc:648] HybridClock initialized: now 1786515614872358 us; error 0 us; skew 500 ppm
I20260812 06:20:14.873263 14936 webserver.cc:533] Webserver started at http://127.14.150.62:42781/ using document root <none> and password file <none>
I20260812 06:20:14.873466 14936 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:14.873518 14936 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:14.873607 14936 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:14.874040 14936 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/master-0-root/instance:
uuid: "7a437783136b46b696f50e51938eb462"
format_stamp: "Formatted at 2026-08-12 06:20:14 on dist-test-slave-bxbt"
I20260812 06:20:14.875618 14936 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:14.876624 15135 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:14.876899 14936 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:14.876971 14936 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/master-0-root
uuid: "7a437783136b46b696f50e51938eb462"
format_stamp: "Formatted at 2026-08-12 06:20:14 on dist-test-slave-bxbt"
I20260812 06:20:14.877075 14936 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-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:14.887022 14936 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:14.887507 14936 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:14.892344 14936 rpc_server.cc:307] RPC server started. Bound to: 127.14.150.62:39077
I20260812 06:20:14.895572 15188 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:14.896938 15187 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.150.62:39077 every 8 connection(s)
I20260812 06:20:14.909927 15188 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462: Bootstrap starting.
I20260812 06:20:14.911046 15188 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:14.912528 15188 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462: No bootstrap required, opened a new log
I20260812 06:20:14.913002 15188 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a437783136b46b696f50e51938eb462" member_type: VOTER }
I20260812 06:20:14.913102 15188 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:14.913126 15188 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7a437783136b46b696f50e51938eb462, State: Initialized, Role: FOLLOWER
I20260812 06:20:14.913300 15188 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [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: "7a437783136b46b696f50e51938eb462" member_type: VOTER }
I20260812 06:20:14.913407 15188 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:14.913444 15188 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:14.913476 15188 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:14.914265 15188 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a437783136b46b696f50e51938eb462" member_type: VOTER }
I20260812 06:20:14.914387 15188 leader_election.cc:304] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [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: 7a437783136b46b696f50e51938eb462; no voters: 
I20260812 06:20:14.914572 15188 leader_election.cc:290] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:14.914767 15191 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:14.914976 15191 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 1 LEADER]: Becoming Leader. State: Replica: 7a437783136b46b696f50e51938eb462, State: Running, Role: LEADER
I20260812 06:20:14.915122 15191 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [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: "7a437783136b46b696f50e51938eb462" member_type: VOTER }
I20260812 06:20:14.915182 15188 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:14.915624 15193 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7a437783136b46b696f50e51938eb462. Latest consensus state: current_term: 1 leader_uuid: "7a437783136b46b696f50e51938eb462" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a437783136b46b696f50e51938eb462" member_type: VOTER } }
I20260812 06:20:14.915604 15192 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7a437783136b46b696f50e51938eb462" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a437783136b46b696f50e51938eb462" member_type: VOTER } }
I20260812 06:20:14.915750 15193 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:14.915782 15192 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:14.916065 15195 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:14.917045 15195 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:14.917361 14936 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:14.919123 15195 catalog_manager.cc:1383] Generated new cluster ID: 8644c942d6fe4a28909924e42891b16c
I20260812 06:20:14.919174 15195 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:14.940011 15195 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:14.940593 15195 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:14.947166 15195 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462: Generated new TSK 0
I20260812 06:20:14.947371 15195 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:14.949796 14936 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:14.951886 15212 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:14.952039 14936 server_base.cc:1061] running on GCE node
W20260812 06:20:14.951886 15210 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:14.951941 15209 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:14.952412 14936 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:14.952458 14936 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:14.952476 14936 hybrid_clock.cc:648] HybridClock initialized: now 1786515614952475 us; error 0 us; skew 500 ppm
I20260812 06:20:14.953393 14936 webserver.cc:533] Webserver started at http://127.14.150.1:42139/ using document root <none> and password file <none>
I20260812 06:20:14.953537 14936 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:14.953584 14936 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:14.953644 14936 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:14.954030 14936 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/instance:
uuid: "dc251232b11b429eb516b0bc82395637"
format_stamp: "Formatted at 2026-08-12 06:20:14 on dist-test-slave-bxbt"
I20260812 06:20:14.955646 14936 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:14.956792 15217 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:14.957127 14936 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:14.957197 14936 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root
uuid: "dc251232b11b429eb516b0bc82395637"
format_stamp: "Formatted at 2026-08-12 06:20:14 on dist-test-slave-bxbt"
I20260812 06:20:14.957258 14936 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-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:14.967588 14936 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:14.968078 14936 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:14.968364 14936 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:14.968873 14936 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:14.968914 14936 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:14.968981 14936 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:14.969022 14936 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:14.973493 14936 rpc_server.cc:307] RPC server started. Bound to: 127.14.150.1:40413
I20260812 06:20:14.973652 15280 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.150.1:40413 every 8 connection(s)
I20260812 06:20:14.982398 15281 heartbeater.cc:344] Connected to a master server at 127.14.150.62:39077
I20260812 06:20:14.982537 15281 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:14.982761 15281 heartbeater.cc:507] Master 127.14.150.62:39077 requested a full tablet report, sending...
I20260812 06:20:14.983487 15152 ts_manager.cc:194] Registered new tserver with Master: dc251232b11b429eb516b0bc82395637 (127.14.150.1:40413)
I20260812 06:20:14.984265 15152 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37126
I20260812 06:20:14.984313 14936 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010393456s
I20260812 06:20:14.992507 15152 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37128:
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:15.002444 15245 tablet_service.cc:1511] Processing CreateTablet for tablet 4be0ea7208cf490cb0fe48dc4b28d702 (DEFAULT_TABLE table=heavy-update-compaction-test [id=aaac51d1516447818ee80eb8afef3fcf]), partition=
I20260812 06:20:15.002738 15245 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4be0ea7208cf490cb0fe48dc4b28d702. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:15.005199 15293 tablet_bootstrap.cc:492] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Bootstrap starting.
I20260812 06:20:15.006095 15293 tablet_bootstrap.cc:654] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.007373 15293 tablet_bootstrap.cc:492] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: No bootstrap required, opened a new log
I20260812 06:20:15.007480 15293 ts_tablet_manager.cc:1403] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:15.008114 15293 raft_consensus.cc:359] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc251232b11b429eb516b0bc82395637" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 40413 } }
I20260812 06:20:15.008211 15293 raft_consensus.cc:385] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.008234 15293 raft_consensus.cc:740] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dc251232b11b429eb516b0bc82395637, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.008412 15293 consensus_queue.cc:260] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [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: "dc251232b11b429eb516b0bc82395637" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 40413 } }
I20260812 06:20:15.008490 15293 raft_consensus.cc:399] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.008562 15293 raft_consensus.cc:493] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.008620 15293 raft_consensus.cc:3060] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.009395 15293 raft_consensus.cc:515] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc251232b11b429eb516b0bc82395637" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 40413 } }
I20260812 06:20:15.009572 15293 leader_election.cc:304] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [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: dc251232b11b429eb516b0bc82395637; no voters: 
I20260812 06:20:15.009810 15293 leader_election.cc:290] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.009963 15295 raft_consensus.cc:2804] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.010210 15293 ts_tablet_manager.cc:1434] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:15.010257 15295 raft_consensus.cc:697] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 1 LEADER]: Becoming Leader. State: Replica: dc251232b11b429eb516b0bc82395637, State: Running, Role: LEADER
I20260812 06:20:15.010309 15281 heartbeater.cc:499] Master 127.14.150.62:39077 was elected leader, sending a full tablet report...
I20260812 06:20:15.010486 15295 consensus_queue.cc:237] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [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: "dc251232b11b429eb516b0bc82395637" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 40413 } }
I20260812 06:20:15.012022 15152 catalog_manager.cc:5719] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 reported cstate change: term changed from 0 to 1, leader changed from <none> to dc251232b11b429eb516b0bc82395637 (127.14.150.1). New cstate: current_term: 1 leader_uuid: "dc251232b11b429eb516b0bc82395637" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc251232b11b429eb516b0bc82395637" member_type: VOTER last_known_addr { host: "127.14.150.1" port: 40413 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:15.074281 14936 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.011s	sys 0.014s
I20260812 06:20:15.224500 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=19.054940
I20260812 06:20:15.377779 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.153s	user 0.115s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":856,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38908,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:15.378551 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702): free 20743880 bytes of WAL
I20260812 06:20:15.378845 15222 log_reader.cc:385] T 4be0ea7208cf490cb0fe48dc4b28d702: removed 2 log segments from log reader
I20260812 06:20:15.378953 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000001 (ops 1-6)
I20260812 06:20:15.379000 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000002 (ops 7-11)
I20260812 06:20:15.384153 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:15.384606 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:15.404426 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.020s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6053,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.404999 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702): 16411395 bytes on disk
I20260812 06:20:15.405542 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:20:15.406082 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:15.559242 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.153s	user 0.115s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":810,"lbm_read_time_us":10529,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25221,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":355,"threads_started":5,"update_count":2000}
I20260812 06:20:15.559953 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:15.609812 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.050s	user 0.019s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19881,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.610337 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:15.622623 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.623270 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:15.786857 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.163s	user 0.118s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":10343,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31337,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:20:15.787559 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:15.838128 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.050s	user 0.030s	sys 0.010s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18586,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.838738 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:15.850023 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.850683 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:16.009179 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.158s	user 0.111s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1102,"lbm_read_time_us":9578,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29528,"lbm_writes_lt_1ms":543,"mutex_wait_us":369,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:20:16.009785 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=10.126437
I20260812 06:20:16.057507 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.046s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20983,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:20:16.058099 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.084848 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.027s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.085316 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.096109 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.096745 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:16.261674 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.165s	user 0.104s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1279,"lbm_read_time_us":10610,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26904,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2500}
I20260812 06:20:16.262220 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:16.315182 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.053s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21015,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.315970 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.327087 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.327608 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:16.501880 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.174s	user 0.082s	sys 0.092s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":537,"lbm_read_time_us":11920,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29219,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:16.502496 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:16.558300 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.056s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20860,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.558954 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.569789 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.002s	sys 0.007s 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:16.570287 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:16.613794 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.043s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1277,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1388,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:16.614557 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702): free 112692367 bytes of WAL
I20260812 06:20:16.614854 15222 log_reader.cc:385] T 4be0ea7208cf490cb0fe48dc4b28d702: removed 11 log segments from log reader
I20260812 06:20:16.614918 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000003 (ops 12-16)
I20260812 06:20:16.614957 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000004 (ops 17-21)
I20260812 06:20:16.614995 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000005 (ops 22-26)
I20260812 06:20:16.615028 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000006 (ops 27-31)
I20260812 06:20:16.615058 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000007 (ops 32-36)
I20260812 06:20:16.615088 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000008 (ops 37-41)
I20260812 06:20:16.615116 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000009 (ops 42-46)
I20260812 06:20:16.615147 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000010 (ops 47-51)
I20260812 06:20:16.615180 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000011 (ops 52-56)
I20260812 06:20:16.615209 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000012 (ops 57-61)
I20260812 06:20:16.615237 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000013 (ops 62-66)
I20260812 06:20:16.639745 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:16.640229 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702): 462 bytes on disk
I20260812 06:20:16.640661 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702) 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:16.641147 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.664927 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.024s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4812,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.665439 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.676050 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.676518 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:16.897975 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.221s	user 0.145s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979754,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":541,"lbm_read_time_us":15923,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37570,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:20:16.898681 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=15.087375
I20260812 06:20:16.946894 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16820189,"delete_count":0,"lbm_write_time_us":21111,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:16.947584 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:16.967759 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.968226 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:17.124159 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.156s	user 0.109s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":429,"lbm_read_time_us":8811,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27721,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:17.124805 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:17.183238 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.058s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22212,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.183954 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:17.195708 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.196321 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:17.390981 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.194s	user 0.127s	sys 0.061s 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":1085,"lbm_read_time_us":11476,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32162,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:20:17.391620 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:17.447067 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.055s	user 0.023s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20882,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.447520 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:17.607985 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.160s	user 0.103s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":998,"lbm_read_time_us":9586,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25345,"lbm_writes_lt_1ms":443,"mutex_wait_us":359,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:20:17.608671 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:17.659636 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.051s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19456,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.660187 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:17.672976 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.673694 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:17.864066 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.190s	user 0.128s	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":1018,"lbm_read_time_us":10070,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32387,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":2500}
I20260812 06:20:17.864884 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:17.917675 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.053s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22789,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.918200 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:17.929877 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.930420 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:18.084589 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.154s	user 0.104s	sys 0.044s 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":296,"lbm_read_time_us":11259,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27746,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:20:18.085423 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=11.118625
I20260812 06:20:18.124583 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.039s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16595,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.125104 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:18.152293 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.027s	user 0.007s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.152880 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:18.163736 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.164395 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:18.197652 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":288,"dirs.run_wall_time_us":1369,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1802,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:18.198381 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702): free 132571311 bytes of WAL
I20260812 06:20:18.198628 15222 log_reader.cc:385] T 4be0ea7208cf490cb0fe48dc4b28d702: removed 13 log segments from log reader
I20260812 06:20:18.198678 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000014 (ops 67-71)
I20260812 06:20:18.198707 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000015 (ops 72-76)
I20260812 06:20:18.198767 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000016 (ops 77-80)
I20260812 06:20:18.198825 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000017 (ops 81-85)
I20260812 06:20:18.198869 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000018 (ops 86-90)
I20260812 06:20:18.198936 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000019 (ops 91-95)
I20260812 06:20:18.198966 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000020 (ops 96-100)
I20260812 06:20:18.199007 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000021 (ops 101-105)
I20260812 06:20:18.199046 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000022 (ops 106-110)
I20260812 06:20:18.199085 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000023 (ops 111-115)
I20260812 06:20:18.199110 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000024 (ops 116-120)
I20260812 06:20:18.199141 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000025 (ops 121-124)
I20260812 06:20:18.199177 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000026 (ops 125-129)
I20260812 06:20:18.228313 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:18.228700 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=3.181125
I20260812 06:20:18.251464 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.023s	user 0.006s	sys 0.013s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":5238,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:20:18.252158 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702): 482 bytes on disk
I20260812 06:20:18.252635 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.253149 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.196750
I20260812 06:20:18.261932 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":3255,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:20:18.262436 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:18.481627 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.219s	user 0.145s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2386,"lbm_read_time_us":15225,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36537,"lbm_writes_lt_1ms":743,"mutex_wait_us":1725,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":119,"threads_started":1,"update_count":3500}
I20260812 06:20:18.482517 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=15.087375
I20260812 06:20:18.533901 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22571,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:18.535398 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:18.550577 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.551112 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:18.731601 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.180s	user 0.121s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":455,"lbm_read_time_us":12001,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31450,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:20:18.732774 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=15.087375
I20260812 06:20:18.788196 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.055s	user 0.036s	sys 0.018s Metrics: {"bytes_written":16656048,"delete_count":0,"lbm_write_time_us":19879,"lbm_writes_lt_1ms":409,"reinsert_count":0,"update_count":2030}
I20260812 06:20:18.788892 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:18.801175 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:20:18.802129 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:18.987881 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.186s	user 0.127s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":12463,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28634,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:20:18.988686 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:19.043743 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.055s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18919,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:19.044497 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.055811 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.056308 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:19.243014 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.187s	user 0.102s	sys 0.080s 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":333,"lbm_read_time_us":12831,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30368,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:20:19.243737 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:19.299481 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.056s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23516,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.300158 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.312130 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.312701 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:19.490743 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.178s	user 0.122s	sys 0.056s 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":326,"lbm_read_time_us":11685,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28298,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:19.491536 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=14.095187
I20260812 06:20:19.546897 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.055s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26061,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.547500 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.560112 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.560587 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:19.709143 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.148s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":430,"lbm_read_time_us":10615,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28630,"lbm_writes_lt_1ms":543,"mutex_wait_us":88,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2500}
I20260812 06:20:19.709934 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=11.118625
I20260812 06:20:19.746654 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.037s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15337,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.747172 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.769476 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.022s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.770059 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.784838 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.785312 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:19.815632 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushMRSOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1299,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1487,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:19.816409 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702): free 133024661 bytes of WAL
I20260812 06:20:19.816691 15222 log_reader.cc:385] T 4be0ea7208cf490cb0fe48dc4b28d702: removed 13 log segments from log reader
I20260812 06:20:19.816753 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000027 (ops 130-134)
I20260812 06:20:19.816793 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000028 (ops 135-139)
I20260812 06:20:19.816830 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000029 (ops 140-144)
I20260812 06:20:19.816855 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000030 (ops 145-149)
I20260812 06:20:19.816885 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000031 (ops 150-154)
I20260812 06:20:19.816915 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000032 (ops 155-158)
I20260812 06:20:19.816941 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000033 (ops 159-163)
I20260812 06:20:19.816972 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000034 (ops 164-168)
I20260812 06:20:19.817008 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000035 (ops 169-173)
I20260812 06:20:19.817039 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000036 (ops 174-178)
I20260812 06:20:19.817065 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000037 (ops 179-183)
I20260812 06:20:19.817092 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000038 (ops 184-188)
I20260812 06:20:19.817119 15222 log.cc:1079] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: Deleting log segment in path: /tmp/dist-test-taskQrGmPH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515609320226-14936-0/minicluster-data/ts-0-root/wals/4be0ea7208cf490cb0fe48dc4b28d702/wal-000000039 (ops 189-193)
I20260812 06:20:19.846719 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: LogGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:19.847211 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702): 493 bytes on disk
I20260812 06:20:19.848022 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: UndoDeltaBlockGCOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":157,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.848869 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.883201 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.034s	user 0.012s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.883852 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=2.188937
I20260812 06:20:19.895416 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: FlushDeltaMemStoresOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.895951 15282 maintenance_manager.cc:419] P dc251232b11b429eb516b0bc82395637: Scheduling MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702): perf score=1.000000
I20260812 06:20:20.009776 14936 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.935s	user 1.848s	sys 0.156s
I20260812 06:20:20.113545 14936 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.001s	sys 0.000s
I20260812 06:20:20.114068 14936 tablet_server.cc:179] TabletServer@127.14.150.1:0 shutting down...
I20260812 06:20:20.119776 15222 maintenance_manager.cc:643] P dc251232b11b429eb516b0bc82395637: MajorDeltaCompactionOp(4be0ea7208cf490cb0fe48dc4b28d702) complete. Timing: real 0.224s	user 0.122s	sys 0.101s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979861,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":799,"lbm_read_time_us":16814,"lbm_reads_lt_1ms":771,"lbm_write_time_us":36425,"lbm_writes_lt_1ms":743,"mutex_wait_us":46,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17664,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:20:20.123224 14936 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:20.123517 14936 tablet_replica.cc:333] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637: stopping tablet replica
I20260812 06:20:20.123769 14936 raft_consensus.cc:2243] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:20.124006 14936 raft_consensus.cc:2272] T 4be0ea7208cf490cb0fe48dc4b28d702 P dc251232b11b429eb516b0bc82395637 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:20.128641 14936 tablet_server.cc:196] TabletServer@127.14.150.1:0 shutdown complete.
I20260812 06:20:20.177618 14936 master.cc:562] Master@127.14.150.62:39077 shutting down...
I20260812 06:20:20.181347 14936 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:20.181541 14936 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:20.181586 14936 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7a437783136b46b696f50e51938eb462: stopping tablet replica
I20260812 06:20:20.194363 14936 master.cc:584] Master@127.14.150.62:39077 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5406 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10945 ms total)

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