[==========] 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:17:08.146086 28046 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.99.190:44953
I20260812 06:17:08.146972 28046 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:17:08.147485 28046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:08.153098 28055 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:17:08.153110 28052 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:17:08.153347 28053 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:17:08.153362 28046 server_base.cc:1061] running on GCE node
I20260812 06:17:08.153752 28046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:08.153894 28046 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:17:08.153959 28046 hybrid_clock.cc:648] HybridClock initialized: now 1786515428153956 us; error 0 us; skew 500 ppm
I20260812 06:17:08.155472 28046 webserver.cc:533] Webserver started at http://127.27.99.190:35171/ using document root <none> and password file <none>
I20260812 06:17:08.155953 28046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:08.156037 28046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:08.156265 28046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:08.157670 28046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/master-0-root/instance:
uuid: "5d140877c2d5400c951cb0c7430086c8"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-6nmv"
I20260812 06:17:08.160820 28046 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:08.162842 28060 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:17:08.163739 28046 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:08.163856 28046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/master-0-root
uuid: "5d140877c2d5400c951cb0c7430086c8"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-6nmv"
I20260812 06:17:08.163947 28046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-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:17:08.184422 28046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:08.184882 28046 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:17:08.185034 28046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:08.191531 28046 rpc_server.cc:307] RPC server started. Bound to: 127.27.99.190:44953
I20260812 06:17:08.191535 28122 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.99.190:44953 every 8 connection(s)
I20260812 06:17:08.193511 28123 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:17:08.197898 28123 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8: Bootstrap starting.
I20260812 06:17:08.199965 28123 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:08.200755 28123 log.cc:826] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:08.202206 28123 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8: No bootstrap required, opened a new log
I20260812 06:17:08.204609 28123 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d140877c2d5400c951cb0c7430086c8" member_type: VOTER }
I20260812 06:17:08.204742 28123 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:08.204864 28123 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5d140877c2d5400c951cb0c7430086c8, State: Initialized, Role: FOLLOWER
I20260812 06:17:08.205435 28123 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [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: "5d140877c2d5400c951cb0c7430086c8" member_type: VOTER }
I20260812 06:17:08.205593 28123 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:08.205685 28123 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:08.205834 28123 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:08.206533 28123 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d140877c2d5400c951cb0c7430086c8" member_type: VOTER }
I20260812 06:17:08.206951 28123 leader_election.cc:304] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [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: 5d140877c2d5400c951cb0c7430086c8; no voters: 
I20260812 06:17:08.207237 28123 leader_election.cc:290] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:08.207403 28127 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:08.207671 28127 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 1 LEADER]: Becoming Leader. State: Replica: 5d140877c2d5400c951cb0c7430086c8, State: Running, Role: LEADER
I20260812 06:17:08.208068 28127 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [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: "5d140877c2d5400c951cb0c7430086c8" member_type: VOTER }
I20260812 06:17:08.208141 28123 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:08.209731 28129 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5d140877c2d5400c951cb0c7430086c8. Latest consensus state: current_term: 1 leader_uuid: "5d140877c2d5400c951cb0c7430086c8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d140877c2d5400c951cb0c7430086c8" member_type: VOTER } }
I20260812 06:17:08.209775 28128 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5d140877c2d5400c951cb0c7430086c8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d140877c2d5400c951cb0c7430086c8" member_type: VOTER } }
I20260812 06:17:08.209874 28129 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:08.209908 28128 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:08.210264 28142 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:08.210381 28046 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:08.212898 28142 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:08.217142 28142 catalog_manager.cc:1383] Generated new cluster ID: 82f020dcbca845a0b6103d8314f55088
I20260812 06:17:08.217198 28142 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:08.225088 28142 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:08.225776 28142 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:08.230274 28142 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8: Generated new TSK 0
I20260812 06:17:08.230756 28142 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:08.242823 28046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:08.245512 28151 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:17:08.245635 28155 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:17:08.245519 28153 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:17:08.245754 28046 server_base.cc:1061] running on GCE node
I20260812 06:17:08.246057 28046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:08.246127 28046 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:17:08.246155 28046 hybrid_clock.cc:648] HybridClock initialized: now 1786515428246153 us; error 0 us; skew 500 ppm
I20260812 06:17:08.247078 28046 webserver.cc:533] Webserver started at http://127.27.99.129:43593/ using document root <none> and password file <none>
I20260812 06:17:08.247246 28046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:08.247300 28046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:08.247365 28046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:08.247798 28046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/instance:
uuid: "d51d34d291264f28bd060ff6cde30473"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-6nmv"
I20260812 06:17:08.249686 28046 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:08.250855 28160 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:17:08.251116 28046 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:08.251205 28046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root
uuid: "d51d34d291264f28bd060ff6cde30473"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-6nmv"
I20260812 06:17:08.251284 28046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-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:17:08.257543 28046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:08.258025 28046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:08.258472 28046 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:08.259294 28046 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:08.259338 28046 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.259444 28046 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:08.259510 28046 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.265702 28046 rpc_server.cc:307] RPC server started. Bound to: 127.27.99.129:38063
I20260812 06:17:08.265736 28237 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.99.129:38063 every 8 connection(s)
I20260812 06:17:08.286635 28238 heartbeater.cc:344] Connected to a master server at 127.27.99.190:44953
I20260812 06:17:08.286921 28238 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:08.287405 28238 heartbeater.cc:507] Master 127.27.99.190:44953 requested a full tablet report, sending...
I20260812 06:17:08.288851 28081 ts_manager.cc:194] Registered new tserver with Master: d51d34d291264f28bd060ff6cde30473 (127.27.99.129:38063)
I20260812 06:17:08.289501 28046 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.02324587s
I20260812 06:17:08.290310 28081 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49864
I20260812 06:17:08.299453 28081 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49870:
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:17:08.314896 28193 tablet_service.cc:1511] Processing CreateTablet for tablet 410f3ce65fe8427684d68d5558bc7e71 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4906b565d1784b04b1b3bd753fe0dbb7]), partition=
I20260812 06:17:08.315347 28193 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 410f3ce65fe8427684d68d5558bc7e71. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:08.318179 28252 tablet_bootstrap.cc:492] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Bootstrap starting.
I20260812 06:17:08.319064 28252 tablet_bootstrap.cc:654] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:08.320139 28252 tablet_bootstrap.cc:492] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: No bootstrap required, opened a new log
I20260812 06:17:08.320245 28252 ts_tablet_manager.cc:1403] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:08.320680 28252 raft_consensus.cc:359] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d51d34d291264f28bd060ff6cde30473" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 38063 } }
I20260812 06:17:08.320773 28252 raft_consensus.cc:385] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:08.320796 28252 raft_consensus.cc:740] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d51d34d291264f28bd060ff6cde30473, State: Initialized, Role: FOLLOWER
I20260812 06:17:08.320987 28252 consensus_queue.cc:260] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [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: "d51d34d291264f28bd060ff6cde30473" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 38063 } }
I20260812 06:17:08.321069 28252 raft_consensus.cc:399] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:08.321120 28252 raft_consensus.cc:493] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:08.321197 28252 raft_consensus.cc:3060] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:08.322105 28252 raft_consensus.cc:515] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d51d34d291264f28bd060ff6cde30473" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 38063 } }
I20260812 06:17:08.322253 28252 leader_election.cc:304] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [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: d51d34d291264f28bd060ff6cde30473; no voters: 
I20260812 06:17:08.322491 28252 leader_election.cc:290] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:08.322582 28254 raft_consensus.cc:2804] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:08.322764 28254 raft_consensus.cc:697] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 1 LEADER]: Becoming Leader. State: Replica: d51d34d291264f28bd060ff6cde30473, State: Running, Role: LEADER
I20260812 06:17:08.322902 28252 ts_tablet_manager.cc:1434] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:08.323014 28254 consensus_queue.cc:237] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [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: "d51d34d291264f28bd060ff6cde30473" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 38063 } }
I20260812 06:17:08.323172 28238 heartbeater.cc:499] Master 127.27.99.190:44953 was elected leader, sending a full tablet report...
I20260812 06:17:08.325585 28081 catalog_manager.cc:5719] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 reported cstate change: term changed from 0 to 1, leader changed from <none> to d51d34d291264f28bd060ff6cde30473 (127.27.99.129). New cstate: current_term: 1 leader_uuid: "d51d34d291264f28bd060ff6cde30473" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d51d34d291264f28bd060ff6cde30473" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 38063 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:08.403405 28046 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.069s	user 0.020s	sys 0.012s
I20260812 06:17:08.516713 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71): perf score=15.086190
I20260812 06:17:08.685788 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.169s	user 0.127s	sys 0.037s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":237,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1046,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42141,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":165,"threads_started":1,"update_count":1500}
I20260812 06:17:08.687175 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling LogGCOp(410f3ce65fe8427684d68d5558bc7e71): free 11976772 bytes of WAL
I20260812 06:17:08.687584 28166 log_reader.cc:385] T 410f3ce65fe8427684d68d5558bc7e71: removed 1 log segments from log reader
I20260812 06:17:08.687839 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000001 (ops 1-6)
I20260812 06:17:08.691550 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: LogGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:08.692085 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:08.715431 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.715827 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:08.725008 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.725386 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:08.872316 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.147s	user 0.114s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733842,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":491,"lbm_read_time_us":10832,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26619,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":304,"threads_started":5,"update_count":2500}
I20260812 06:17:08.872888 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=10.126437
I20260812 06:17:08.923964 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.051s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17520,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:08.924489 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71): 12308961 bytes on disk
I20260812 06:17:08.924980 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:08.925439 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:08.937989 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.012s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.938453 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:09.064743 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.126s	user 0.077s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":448,"lbm_read_time_us":10318,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24088,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:17:09.065426 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=10.126437
I20260812 06:17:09.105649 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.040s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17288,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.106374 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.123076 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.123610 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:09.253391 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.130s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1019,"lbm_read_time_us":8526,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24893,"lbm_writes_lt_1ms":443,"mutex_wait_us":355,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:09.253931 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=11.118625
I20260812 06:17:09.298954 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.045s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14815,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:09.299582 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.309459 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.310001 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:09.455468 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.145s	user 0.108s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":603,"lbm_read_time_us":11341,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24367,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:09.456246 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=11.118625
I20260812 06:17:09.492878 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.036s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16220,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:09.493367 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.502621 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3404,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.503120 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:09.641693 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.138s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":836,"lbm_read_time_us":8638,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27586,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:17:09.642364 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=10.126437
I20260812 06:17:09.680136 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16564,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.680631 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.691421 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.691916 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:09.808653 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.117s	user 0.092s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":703,"lbm_read_time_us":8959,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21006,"lbm_writes_lt_1ms":443,"mutex_wait_us":270,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:09.809366 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=10.126437
I20260812 06:17:09.844535 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.035s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14703,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.845235 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.855764 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.856305 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:09.882012 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":148,"dirs.run_wall_time_us":1279,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1474,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:09.882917 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling LogGCOp(410f3ce65fe8427684d68d5558bc7e71): free 116849451 bytes of WAL
I20260812 06:17:09.883136 28166 log_reader.cc:385] T 410f3ce65fe8427684d68d5558bc7e71: removed 12 log segments from log reader
I20260812 06:17:09.883185 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000002 (ops 7-11)
I20260812 06:17:09.883224 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000003 (ops 12-16)
I20260812 06:17:09.883258 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000004 (ops 17-20)
I20260812 06:17:09.883286 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000005 (ops 21-25)
I20260812 06:17:09.883320 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000006 (ops 26-30)
I20260812 06:17:09.883353 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000007 (ops 31-34)
I20260812 06:17:09.883385 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000008 (ops 35-39)
I20260812 06:17:09.883417 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000009 (ops 40-44)
I20260812 06:17:09.883452 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000010 (ops 45-49)
I20260812 06:17:09.883487 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000011 (ops 50-54)
I20260812 06:17:09.883519 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000012 (ops 55-58)
I20260812 06:17:09.883550 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000013 (ops 59-63)
I20260812 06:17:09.910732 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: LogGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:09.911120 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.928566 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.017s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.929018 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71): 462 bytes on disk
I20260812 06:17:09.929417 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.929896 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:09.939612 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.939940 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:10.118840 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.179s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836374,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":196,"lbm_read_time_us":12196,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36918,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:17:10.119495 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:10.174633 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.054s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21786,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.175088 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:10.184962 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.185575 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:10.336089 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.150s	user 0.078s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":11958,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26498,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:10.336894 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=11.118625
I20260812 06:17:10.375710 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.039s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16171,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:10.376207 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:10.395604 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.019s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.396095 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:10.408603 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4869,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.409032 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:10.578685 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.169s	user 0.117s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":202,"lbm_read_time_us":12961,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28833,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:17:10.579334 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:10.637051 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.058s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22473,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.637526 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:10.647259 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.647652 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:10.812269 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.164s	user 0.103s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":12558,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27349,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":134784,"update_count":2500}
I20260812 06:17:10.812994 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:10.871332 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.058s	user 0.014s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18336,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.871840 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:10.881954 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.882337 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:11.045734 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.163s	user 0.116s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":81,"lbm_read_time_us":11611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28210,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:17:11.046497 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=11.118625
I20260812 06:17:11.077430 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.031s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13333,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:11.078029 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:11.099211 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.021s	user 0.010s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5137,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":450}
I20260812 06:17:11.099925 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:11.250751 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.151s	user 0.093s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":9656,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25146,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:11.251547 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:11.295608 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.044s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19490,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.296094 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:11.306581 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.307185 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:11.338094 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1208,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1764,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":896}
I20260812 06:17:11.338809 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling LogGCOp(410f3ce65fe8427684d68d5558bc7e71): free 129320554 bytes of WAL
I20260812 06:17:11.339039 28166 log_reader.cc:385] T 410f3ce65fe8427684d68d5558bc7e71: removed 13 log segments from log reader
I20260812 06:17:11.339085 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000014 (ops 64-68)
I20260812 06:17:11.339114 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000015 (ops 69-72)
I20260812 06:17:11.339170 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000016 (ops 73-77)
I20260812 06:17:11.339213 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000017 (ops 78-82)
I20260812 06:17:11.339260 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000018 (ops 83-87)
I20260812 06:17:11.339318 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000019 (ops 88-92)
I20260812 06:17:11.339346 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000020 (ops 93-97)
I20260812 06:17:11.339393 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000021 (ops 98-102)
I20260812 06:17:11.339430 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000022 (ops 103-107)
I20260812 06:17:11.339466 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000023 (ops 108-112)
I20260812 06:17:11.339501 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000024 (ops 113-116)
I20260812 06:17:11.339538 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000025 (ops 117-121)
I20260812 06:17:11.339574 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000026 (ops 122-126)
I20260812 06:17:11.367359 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: LogGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.028s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:17:11.367808 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71): 482 bytes on disk
I20260812 06:17:11.368279 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71) 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:17:11.368748 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=6.157687
I20260812 06:17:11.400911 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.032s	user 0.004s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10128,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:11.401552 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling LogGCOp(410f3ce65fe8427684d68d5558bc7e71): free 11564883 bytes of WAL
I20260812 06:17:11.401859 28166 log_reader.cc:385] T 410f3ce65fe8427684d68d5558bc7e71: removed 1 log segments from log reader
I20260812 06:17:11.401930 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000027 (ops 127-130)
I20260812 06:17:11.404430 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: LogGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:11.404776 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:11.635260 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.230s	user 0.139s	sys 0.087s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938667,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":839,"lbm_read_time_us":18221,"lbm_reads_lt_1ms":765,"lbm_write_time_us":41407,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:17:11.635864 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=18.063937
I20260812 06:17:11.705099 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.067s	user 0.052s	sys 0.012s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":30578,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:11.705492 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:11.715585 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.716257 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:11.918396 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.202s	user 0.133s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836143,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1459,"lbm_read_time_us":16123,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32410,"lbm_writes_lt_1ms":643,"mutex_wait_us":398,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":3000}
I20260812 06:17:11.919111 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:11.969295 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21393,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.969802 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:11.986753 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.987331 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:12.161470 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.174s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":624,"lbm_read_time_us":14791,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30435,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:17:12.162146 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:12.215384 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.053s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22828,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.215943 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:12.234107 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.018s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.234838 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:12.404932 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.170s	user 0.100s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":12460,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28892,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:12.405583 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:12.464282 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.058s	user 0.025s	sys 0.026s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.464797 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:12.480741 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.481321 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:12.663408 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.182s	user 0.124s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":810,"lbm_read_time_us":11750,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29369,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:12.664053 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=14.095187
I20260812 06:17:12.722532 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.058s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24316,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.723129 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:12.741555 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.018s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.742080 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:12.771579 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushMRSOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.029s	user 0.026s	sys 0.002s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1213,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1466,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:12.772296 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling LogGCOp(410f3ce65fe8427684d68d5558bc7e71): free 112692610 bytes of WAL
I20260812 06:17:12.772541 28166 log_reader.cc:385] T 410f3ce65fe8427684d68d5558bc7e71: removed 11 log segments from log reader
I20260812 06:17:12.772614 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000028 (ops 131-135)
I20260812 06:17:12.772666 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000029 (ops 136-140)
I20260812 06:17:12.772723 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000030 (ops 141-145)
I20260812 06:17:12.772776 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000031 (ops 146-150)
I20260812 06:17:12.772811 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000032 (ops 151-155)
I20260812 06:17:12.772846 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000033 (ops 156-160)
I20260812 06:17:12.772918 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000034 (ops 161-165)
I20260812 06:17:12.772954 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000035 (ops 166-170)
I20260812 06:17:12.772985 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000036 (ops 171-175)
I20260812 06:17:12.773020 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000037 (ops 176-180)
I20260812 06:17:12.773052 28166 log.cc:1079] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/410f3ce65fe8427684d68d5558bc7e71/wal-000000038 (ops 181-185)
I20260812 06:17:12.797086 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: LogGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:12.797485 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71): 448 bytes on disk
I20260812 06:17:12.798039 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: UndoDeltaBlockGCOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.798632 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=3.181125
I20260812 06:17:12.819087 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.020s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6625,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:12.819483 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:12.829186 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.829598 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:13.062325 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.233s	user 0.126s	sys 0.095s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938775,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":635,"lbm_read_time_us":14721,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38771,"lbm_writes_lt_1ms":743,"mutex_wait_us":368,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":121984,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:17:13.063135 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=18.063937
I20260812 06:17:13.139024 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.075s	user 0.050s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31202,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:13.139513 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71): perf score=2.188937
I20260812 06:17:13.149971 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: FlushDeltaMemStoresOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.150468 28239 maintenance_manager.cc:419] P d51d34d291264f28bd060ff6cde30473: Scheduling MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71): perf score=1.000000
I20260812 06:17:13.192572 28046 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.789s	user 1.785s	sys 0.103s
I20260812 06:17:13.257844 28046 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.003s	sys 0.000s
I20260812 06:17:13.258574 28046 tablet_server.cc:179] TabletServer@127.27.99.129:0 shutting down...
I20260812 06:17:13.319973 28166 maintenance_manager.cc:643] P d51d34d291264f28bd060ff6cde30473: MajorDeltaCompactionOp(410f3ce65fe8427684d68d5558bc7e71) complete. Timing: real 0.169s	user 0.120s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":559,"lbm_read_time_us":15150,"lbm_reads_lt_1ms":668,"lbm_write_time_us":29113,"lbm_writes_lt_1ms":643,"mutex_wait_us":76,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:17:13.320779 28046 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:13.321192 28046 tablet_replica.cc:333] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473: stopping tablet replica
I20260812 06:17:13.321435 28046 raft_consensus.cc:2243] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:13.321666 28046 raft_consensus.cc:2272] T 410f3ce65fe8427684d68d5558bc7e71 P d51d34d291264f28bd060ff6cde30473 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:13.337430 28046 tablet_server.cc:196] TabletServer@127.27.99.129:0 shutdown complete.
I20260812 06:17:13.374203 28046 master.cc:562] Master@127.27.99.190:44953 shutting down...
I20260812 06:17:13.378167 28046 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:13.378368 28046 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:13.378461 28046 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5d140877c2d5400c951cb0c7430086c8: stopping tablet replica
I20260812 06:17:13.390676 28046 master.cc:584] Master@127.27.99.190:44953 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5332 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:13.488080 28046 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.99.190:44967
I20260812 06:17:13.488497 28046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:13.490746 28274 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:17:13.490789 28273 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:17:13.490805 28046 server_base.cc:1061] running on GCE node
W20260812 06:17:13.490880 28277 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:17:13.491101 28046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:13.491142 28046 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:17:13.491158 28046 hybrid_clock.cc:648] HybridClock initialized: now 1786515433491157 us; error 0 us; skew 500 ppm
I20260812 06:17:13.492027 28046 webserver.cc:533] Webserver started at http://127.27.99.190:43787/ using document root <none> and password file <none>
I20260812 06:17:13.492205 28046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:13.492247 28046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:13.492341 28046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:13.492723 28046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/master-0-root/instance:
uuid: "02fe2a8a8a6347ef88d64830d957f1d4"
format_stamp: "Formatted at 2026-08-12 06:17:13 on dist-test-slave-6nmv"
I20260812 06:17:13.494570 28046 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:13.495482 28283 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:17:13.495762 28046 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:13.495820 28046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/master-0-root
uuid: "02fe2a8a8a6347ef88d64830d957f1d4"
format_stamp: "Formatted at 2026-08-12 06:17:13 on dist-test-slave-6nmv"
I20260812 06:17:13.495868 28046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-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:17:13.508809 28046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:13.509074 28046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:13.512836 28046 rpc_server.cc:307] RPC server started. Bound to: 127.27.99.190:44967
I20260812 06:17:13.513993 28342 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.99.190:44967 every 8 connection(s)
I20260812 06:17:13.514968 28343 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:17:13.518059 28343 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4: Bootstrap starting.
I20260812 06:17:13.518832 28343 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:13.519819 28343 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4: No bootstrap required, opened a new log
I20260812 06:17:13.520188 28343 raft_consensus.cc:359] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02fe2a8a8a6347ef88d64830d957f1d4" member_type: VOTER }
I20260812 06:17:13.520287 28343 raft_consensus.cc:385] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:13.520347 28343 raft_consensus.cc:740] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 02fe2a8a8a6347ef88d64830d957f1d4, State: Initialized, Role: FOLLOWER
I20260812 06:17:13.520509 28343 consensus_queue.cc:260] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [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: "02fe2a8a8a6347ef88d64830d957f1d4" member_type: VOTER }
I20260812 06:17:13.520596 28343 raft_consensus.cc:399] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:13.520639 28343 raft_consensus.cc:493] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:13.520699 28343 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:13.521306 28343 raft_consensus.cc:515] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02fe2a8a8a6347ef88d64830d957f1d4" member_type: VOTER }
I20260812 06:17:13.521456 28343 leader_election.cc:304] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [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: 02fe2a8a8a6347ef88d64830d957f1d4; no voters: 
I20260812 06:17:13.521636 28343 leader_election.cc:290] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:13.521761 28348 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:13.522019 28348 raft_consensus.cc:697] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 1 LEADER]: Becoming Leader. State: Replica: 02fe2a8a8a6347ef88d64830d957f1d4, State: Running, Role: LEADER
I20260812 06:17:13.522086 28343 sys_catalog.cc:565] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:13.522190 28348 consensus_queue.cc:237] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [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: "02fe2a8a8a6347ef88d64830d957f1d4" member_type: VOTER }
I20260812 06:17:13.522596 28349 sys_catalog.cc:455] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "02fe2a8a8a6347ef88d64830d957f1d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02fe2a8a8a6347ef88d64830d957f1d4" member_type: VOTER } }
I20260812 06:17:13.522699 28349 sys_catalog.cc:458] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:13.522867 28350 sys_catalog.cc:455] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 02fe2a8a8a6347ef88d64830d957f1d4. Latest consensus state: current_term: 1 leader_uuid: "02fe2a8a8a6347ef88d64830d957f1d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02fe2a8a8a6347ef88d64830d957f1d4" member_type: VOTER } }
I20260812 06:17:13.522940 28350 sys_catalog.cc:458] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:13.522957 28356 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:13.523836 28356 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:13.524063 28046 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:13.525656 28356 catalog_manager.cc:1383] Generated new cluster ID: 181aaf0a5773412ab8bb3c7452beca3b
I20260812 06:17:13.525714 28356 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:13.550660 28356 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:13.551194 28356 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:13.555577 28356 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4: Generated new TSK 0
I20260812 06:17:13.555747 28356 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:13.588616 28046 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:13.590636 28370 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:17:13.590773 28371 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:17:13.590704 28046 server_base.cc:1061] running on GCE node
W20260812 06:17:13.590678 28373 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:17:13.591059 28046 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:13.591120 28046 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:17:13.591150 28046 hybrid_clock.cc:648] HybridClock initialized: now 1786515433591150 us; error 0 us; skew 500 ppm
I20260812 06:17:13.591949 28046 webserver.cc:533] Webserver started at http://127.27.99.129:40581/ using document root <none> and password file <none>
I20260812 06:17:13.592136 28046 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:13.592206 28046 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:13.592280 28046 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:13.592650 28046 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/instance:
uuid: "62baa88856d1415bbbf4b200eafeb326"
format_stamp: "Formatted at 2026-08-12 06:17:13 on dist-test-slave-6nmv"
I20260812 06:17:13.594218 28046 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:13.595043 28380 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:17:13.595278 28046 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:13.595362 28046 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root
uuid: "62baa88856d1415bbbf4b200eafeb326"
format_stamp: "Formatted at 2026-08-12 06:17:13 on dist-test-slave-6nmv"
I20260812 06:17:13.595443 28046 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-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:17:13.606845 28046 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:13.607120 28046 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:13.607365 28046 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:13.607738 28046 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:13.607792 28046 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:13.607839 28046 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:13.607883 28046 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:13.611975 28046 rpc_server.cc:307] RPC server started. Bound to: 127.27.99.129:40099
I20260812 06:17:13.613433 28455 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.99.129:40099 every 8 connection(s)
I20260812 06:17:13.626462 28456 heartbeater.cc:344] Connected to a master server at 127.27.99.190:44967
I20260812 06:17:13.626570 28456 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:13.626763 28456 heartbeater.cc:507] Master 127.27.99.190:44967 requested a full tablet report, sending...
I20260812 06:17:13.627380 28303 ts_manager.cc:194] Registered new tserver with Master: 62baa88856d1415bbbf4b200eafeb326 (127.27.99.129:40099)
I20260812 06:17:13.628023 28303 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56914
I20260812 06:17:13.628212 28046 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015394952s
I20260812 06:17:13.634337 28303 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56916:
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:17:13.642532 28412 tablet_service.cc:1511] Processing CreateTablet for tablet 2993c19a3cc84dc99f1c1fecfa39685b (DEFAULT_TABLE table=heavy-update-compaction-test [id=86501ec93c214f248dac11b48a1eae59]), partition=
I20260812 06:17:13.642730 28412 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2993c19a3cc84dc99f1c1fecfa39685b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:13.644352 28470 tablet_bootstrap.cc:492] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Bootstrap starting.
I20260812 06:17:13.645193 28470 tablet_bootstrap.cc:654] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:13.646135 28470 tablet_bootstrap.cc:492] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: No bootstrap required, opened a new log
I20260812 06:17:13.646202 28470 ts_tablet_manager.cc:1403] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:13.646522 28470 raft_consensus.cc:359] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62baa88856d1415bbbf4b200eafeb326" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 40099 } }
I20260812 06:17:13.646593 28470 raft_consensus.cc:385] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:13.646615 28470 raft_consensus.cc:740] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 62baa88856d1415bbbf4b200eafeb326, State: Initialized, Role: FOLLOWER
I20260812 06:17:13.646760 28470 consensus_queue.cc:260] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [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: "62baa88856d1415bbbf4b200eafeb326" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 40099 } }
I20260812 06:17:13.646854 28470 raft_consensus.cc:399] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:13.646939 28470 raft_consensus.cc:493] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:13.647032 28470 raft_consensus.cc:3060] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:13.647708 28470 raft_consensus.cc:515] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62baa88856d1415bbbf4b200eafeb326" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 40099 } }
I20260812 06:17:13.647845 28470 leader_election.cc:304] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [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: 62baa88856d1415bbbf4b200eafeb326; no voters: 
I20260812 06:17:13.648108 28470 leader_election.cc:290] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:13.648309 28472 raft_consensus.cc:2804] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:13.648453 28456 heartbeater.cc:499] Master 127.27.99.190:44967 was elected leader, sending a full tablet report...
I20260812 06:17:13.648454 28470 ts_tablet_manager.cc:1434] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:13.648537 28472 raft_consensus.cc:697] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 1 LEADER]: Becoming Leader. State: Replica: 62baa88856d1415bbbf4b200eafeb326, State: Running, Role: LEADER
I20260812 06:17:13.648684 28472 consensus_queue.cc:237] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [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: "62baa88856d1415bbbf4b200eafeb326" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 40099 } }
I20260812 06:17:13.650213 28303 catalog_manager.cc:5719] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 reported cstate change: term changed from 0 to 1, leader changed from <none> to 62baa88856d1415bbbf4b200eafeb326 (127.27.99.129). New cstate: current_term: 1 leader_uuid: "62baa88856d1415bbbf4b200eafeb326" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62baa88856d1415bbbf4b200eafeb326" member_type: VOTER last_known_addr { host: "127.27.99.129" port: 40099 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:13.708061 28046 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.007s
I20260812 06:17:13.863763 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=23.023690
I20260812 06:17:14.021574 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.158s	user 0.130s	sys 0.024s Metrics: {"bytes_written":12348516,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":726,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43303,"lbm_writes_lt_1ms":858,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":6528,"update_count":1505}
I20260812 06:17:14.022166 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b): free 20743880 bytes of WAL
I20260812 06:17:14.022399 28385 log_reader.cc:385] T 2993c19a3cc84dc99f1c1fecfa39685b: removed 2 log segments from log reader
I20260812 06:17:14.022450 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000001 (ops 1-6)
I20260812 06:17:14.022485 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000002 (ops 7-11)
I20260812 06:17:14.027439 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:14.027783 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b): 20513815 bytes on disk
I20260812 06:17:14.028192 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.028625 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:14.043228 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.014s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6263,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:14.043596 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:14.196264 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.153s	user 0.112s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":327,"lbm_read_time_us":11726,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27666,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":285,"threads_started":5,"update_count":2000}
I20260812 06:17:14.196897 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=11.118625
I20260812 06:17:14.230662 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.034s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14916,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:14.231220 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:14.243755 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.244251 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:14.393317 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.149s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":11647,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24063,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2000}
I20260812 06:17:14.394037 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=11.118625
I20260812 06:17:14.447992 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.054s	user 0.016s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19818,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:14.448554 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=6.157687
I20260812 06:17:14.471875 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.023s	user 0.009s	sys 0.012s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10172,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:14.472326 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:14.663564 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.191s	user 0.117s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":538,"lbm_read_time_us":13682,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30465,"lbm_writes_lt_1ms":543,"mutex_wait_us":288,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:17:14.664258 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:14.719336 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.055s	user 0.024s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25561,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.719792 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:14.731564 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.732012 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:14.888726 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.157s	user 0.108s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":9049,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33237,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:17:14.889410 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:14.934708 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.045s	user 0.035s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19681,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.935371 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:14.946985 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.947568 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:15.124756 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.177s	user 0.125s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":10462,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31723,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:17:15.125749 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:15.202809 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.077s	user 0.043s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":33625,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.203542 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:15.233258 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.029s	user 0.014s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.234089 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:15.291463 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.057s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":412,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":195,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2519,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:15.292433 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b): 462 bytes on disk
I20260812 06:17:15.292984 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.293694 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=3.181125
I20260812 06:17:15.311862 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6409,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.312387 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b): free 121006432 bytes of WAL
I20260812 06:17:15.312690 28385 log_reader.cc:385] T 2993c19a3cc84dc99f1c1fecfa39685b: removed 12 log segments from log reader
I20260812 06:17:15.312750 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000003 (ops 12-16)
I20260812 06:17:15.312839 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000004 (ops 17-21)
I20260812 06:17:15.312917 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000005 (ops 22-26)
I20260812 06:17:15.312980 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000006 (ops 27-31)
I20260812 06:17:15.313050 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000007 (ops 32-36)
I20260812 06:17:15.313103 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000008 (ops 37-41)
I20260812 06:17:15.313169 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000009 (ops 42-46)
I20260812 06:17:15.313244 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000010 (ops 47-51)
I20260812 06:17:15.313310 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000011 (ops 52-56)
I20260812 06:17:15.313385 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000012 (ops 57-60)
I20260812 06:17:15.313442 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000013 (ops 61-65)
I20260812 06:17:15.313517 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000014 (ops 66-70)
I20260812 06:17:15.348397 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.036s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:15.349021 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:15.392352 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.043s	user 0.014s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":11290,"lbm_writes_lt_1ms":93,"mutex_wait_us":31,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.395705 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:15.419986 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.024s	user 0.014s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":9316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.420538 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:15.855489 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.435s	user 0.295s	sys 0.139s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123266,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":306,"lbm_read_time_us":28155,"lbm_reads_lt_1ms":875,"lbm_write_time_us":82498,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":644,"threads_started":7,"update_count":4000}
I20260812 06:17:15.856642 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=18.063937
I20260812 06:17:15.956473 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.099s	user 0.060s	sys 0.036s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":45365,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:15.957058 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=3.181125
I20260812 06:17:15.986994 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.030s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8297,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.987779 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:16.009011 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.021s	user 0.014s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7747,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.009977 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:16.475265 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.465s	user 0.353s	sys 0.089s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020619,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1319,"lbm_read_time_us":29836,"lbm_reads_lt_1ms":773,"lbm_write_time_us":85113,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14464,"thread_start_us":933,"threads_started":6,"update_count":3500}
I20260812 06:17:16.476432 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=18.063937
I20260812 06:17:16.697454 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.221s	user 0.100s	sys 0.090s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":113316,"lbm_writes_1-10_ms":4,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":498,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:17:16.698731 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:16.732950 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.034s	user 0.019s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":13327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.733732 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:17.064379 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.330s	user 0.230s	sys 0.100s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":544,"lbm_read_time_us":30886,"lbm_reads_lt_1ms":672,"lbm_write_time_us":69982,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":40704,"thread_start_us":500,"threads_started":5,"update_count":3000}
I20260812 06:17:17.065474 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=10.126437
I20260812 06:17:17.175778 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.110s	user 0.036s	sys 0.046s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":38007,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.177177 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:17.246219 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.069s	user 0.036s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":17709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.247287 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:17.281204 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":13345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.282234 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:17.545650 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.263s	user 0.209s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815805,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":349,"lbm_read_time_us":18871,"lbm_reads_lt_1ms":573,"lbm_write_time_us":53774,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2500}
I20260812 06:17:17.547159 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:17.624471 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.077s	user 0.034s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":35725,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.625031 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:17.641469 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.642051 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:17.806239 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.164s	user 0.126s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":10970,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30088,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:17.806917 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:17.861568 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.054s	user 0.017s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.862047 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:17.901705 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.039s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1527,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:17.902632 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b): 473 bytes on disk
I20260812 06:17:17.903084 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.903554 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=3.181125
I20260812 06:17:17.919124 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.015s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:17.919581 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b): free 124257245 bytes of WAL
I20260812 06:17:17.919821 28385 log_reader.cc:385] T 2993c19a3cc84dc99f1c1fecfa39685b: removed 12 log segments from log reader
I20260812 06:17:17.919878 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000015 (ops 71-74)
I20260812 06:17:17.919904 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000016 (ops 75-79)
I20260812 06:17:17.919960 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000017 (ops 80-84)
I20260812 06:17:17.920003 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000018 (ops 85-89)
I20260812 06:17:17.920042 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000019 (ops 90-94)
I20260812 06:17:17.920095 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000020 (ops 95-99)
I20260812 06:17:17.920123 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000021 (ops 100-104)
I20260812 06:17:17.920156 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000022 (ops 105-109)
I20260812 06:17:17.920192 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000023 (ops 110-114)
I20260812 06:17:17.920229 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000024 (ops 115-119)
I20260812 06:17:17.920265 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000025 (ops 120-124)
I20260812 06:17:17.920310 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000026 (ops 125-129)
I20260812 06:17:17.946548 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:17.947078 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:17.963369 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.016s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4477,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.963871 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:17.974313 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.974869 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:18.196700 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.222s	user 0.122s	sys 0.095s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":645,"lbm_read_time_us":16848,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38693,"lbm_writes_lt_1ms":743,"mutex_wait_us":120,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":115,"threads_started":1,"update_count":3500}
I20260812 06:17:18.197407 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=15.087375
I20260812 06:17:18.248297 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.051s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":20411,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:18.248791 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:18.259652 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4184710,"delete_count":0,"lbm_write_time_us":4123,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:17:18.260066 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:18.268913 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":3641,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:18.269299 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:18.434314 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.165s	user 0.112s	sys 0.051s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":288,"lbm_read_time_us":13652,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35584,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":3000}
I20260812 06:17:18.435032 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:18.494474 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.059s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23594,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.495078 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:18.513238 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.513787 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:18.663724 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.150s	user 0.101s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":61,"lbm_read_time_us":9630,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28874,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:18.664403 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=11.118625
I20260812 06:17:18.700889 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.036s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15282,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:18.701493 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:18.727802 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5303,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.728307 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:18.738870 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.010s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.739317 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:18.926218 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.187s	user 0.139s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":826,"lbm_read_time_us":12743,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30962,"lbm_writes_lt_1ms":543,"mutex_wait_us":404,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:17:18.926990 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:18.984817 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.058s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409950,"delete_count":0,"lbm_write_time_us":22008,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.985360 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:18.995829 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.996529 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:19.170454 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.174s	user 0.118s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":390,"lbm_read_time_us":13321,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29604,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:19.170975 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=14.095187
I20260812 06:17:19.236080 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.065s	user 0.032s	sys 0.022s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24263,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.236614 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:19.248256 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.248926 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:19.276227 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushMRSOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.027s	user 0.021s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":310,"dirs.run_wall_time_us":1489,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1446,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:19.276901 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b): free 112239561 bytes of WAL
I20260812 06:17:19.277136 28385 log_reader.cc:385] T 2993c19a3cc84dc99f1c1fecfa39685b: removed 11 log segments from log reader
I20260812 06:17:19.277180 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000027 (ops 130-134)
I20260812 06:17:19.277208 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000028 (ops 135-139)
I20260812 06:17:19.277273 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000029 (ops 140-144)
I20260812 06:17:19.277309 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000030 (ops 145-149)
I20260812 06:17:19.277344 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000031 (ops 150-154)
I20260812 06:17:19.277396 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000032 (ops 155-159)
I20260812 06:17:19.277452 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000033 (ops 160-164)
I20260812 06:17:19.277490 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000034 (ops 165-168)
I20260812 06:17:19.277524 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000035 (ops 169-173)
I20260812 06:17:19.277559 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000036 (ops 174-178)
I20260812 06:17:19.277594 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000037 (ops 179-183)
I20260812 06:17:19.300935 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.024s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:17:19.301348 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b): 448 bytes on disk
I20260812 06:17:19.301993 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: UndoDeltaBlockGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":138,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.302538 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=3.181125
I20260812 06:17:19.320279 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.018s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4486,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:19.320720 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b): free 12017954 bytes of WAL
I20260812 06:17:19.320955 28385 log_reader.cc:385] T 2993c19a3cc84dc99f1c1fecfa39685b: removed 1 log segments from log reader
I20260812 06:17:19.321031 28385 log.cc:1079] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: Deleting log segment in path: /tmp/dist-test-taskFW0sEF/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428136063-28046-0/minicluster-data/ts-0-root/wals/2993c19a3cc84dc99f1c1fecfa39685b/wal-000000038 (ops 184-188)
I20260812 06:17:19.323423 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: LogGCOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:19.323736 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:19.334299 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4081,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.334897 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:19.553627 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.218s	user 0.159s	sys 0.049s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1083,"lbm_read_time_us":16623,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37653,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:17:19.554363 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=18.063937
I20260812 06:17:19.610746 28046 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.903s	user 2.080s	sys 0.207s
I20260812 06:17:19.613953 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.059s	user 0.045s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29097,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.614475 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=2.188937
I20260812 06:17:19.624662 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: FlushDeltaMemStoresOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":500}
I20260812 06:17:19.625042 28457 maintenance_manager.cc:419] P 62baa88856d1415bbbf4b200eafeb326: Scheduling MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b): perf score=1.000000
I20260812 06:17:19.636955 28046 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.026s	user 0.001s	sys 0.000s
I20260812 06:17:19.637490 28046 tablet_server.cc:179] TabletServer@127.27.99.129:0 shutting down...
I20260812 06:17:19.775823 28385 maintenance_manager.cc:643] P 62baa88856d1415bbbf4b200eafeb326: MajorDeltaCompactionOp(2993c19a3cc84dc99f1c1fecfa39685b) complete. Timing: real 0.151s	user 0.099s	sys 0.051s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614712,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":10582,"lbm_reads_lt_1ms":618,"lbm_write_time_us":28982,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":3000}
I20260812 06:17:19.776465 28046 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:19.776714 28046 tablet_replica.cc:333] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326: stopping tablet replica
I20260812 06:17:19.776860 28046 raft_consensus.cc:2243] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:19.777034 28046 raft_consensus.cc:2272] T 2993c19a3cc84dc99f1c1fecfa39685b P 62baa88856d1415bbbf4b200eafeb326 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:19.790484 28046 tablet_server.cc:196] TabletServer@127.27.99.129:0 shutdown complete.
I20260812 06:17:19.828473 28046 master.cc:562] Master@127.27.99.190:44967 shutting down...
I20260812 06:17:19.832413 28046 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:19.832603 28046 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:19.832690 28046 tablet_replica.cc:333] T 00000000000000000000000000000000 P 02fe2a8a8a6347ef88d64830d957f1d4: stopping tablet replica
I20260812 06:17:19.845746 28046 master.cc:584] Master@127.27.99.190:44967 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6456 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11789 ms total)

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