[==========] 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:31.920195  1208 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.46.62:33417
I20260812 06:17:31.921729  1208 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:31.922586  1208 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:31.930727  1214 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:31.930784  1213 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:31.930912  1208 server_base.cc:1061] running on GCE node
W20260812 06:17:31.931034  1216 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:31.931591  1208 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:31.931707  1208 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:31.931737  1208 hybrid_clock.cc:648] HybridClock initialized: now 1786515451931734 us; error 0 us; skew 500 ppm
I20260812 06:17:31.934206  1208 webserver.cc:533] Webserver started at http://127.1.46.62:45607/ using document root <none> and password file <none>
I20260812 06:17:31.934830  1208 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:31.934900  1208 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:31.935153  1208 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:31.937098  1208 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/master-0-root/instance:
uuid: "1fef819b3fb64861908ceb6f35ac09d0"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-kvfs"
I20260812 06:17:31.942374  1208 fs_manager.cc:696] Time spent creating directory manager: real 0.005s	user 0.005s	sys 0.000s
I20260812 06:17:31.945475  1223 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:31.947355  1208 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:31.947602  1208 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/master-0-root
uuid: "1fef819b3fb64861908ceb6f35ac09d0"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-kvfs"
I20260812 06:17:31.947745  1208 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-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:31.972813  1208 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:31.973608  1208 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:31.973821  1208 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:31.982955  1311 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.46.62:33417 every 8 connection(s)
I20260812 06:17:31.982971  1208 rpc_server.cc:307] RPC server started. Bound to: 127.1.46.62:33417
I20260812 06:17:31.986115  1312 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:31.992436  1312 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0: Bootstrap starting.
I20260812 06:17:31.994971  1312 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:31.996104  1312 log.cc:826] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:31.998144  1312 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0: No bootstrap required, opened a new log
I20260812 06:17:32.001579  1312 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1fef819b3fb64861908ceb6f35ac09d0" member_type: VOTER }
I20260812 06:17:32.001802  1312 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:32.001896  1312 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1fef819b3fb64861908ceb6f35ac09d0, State: Initialized, Role: FOLLOWER
I20260812 06:17:32.002597  1312 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [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: "1fef819b3fb64861908ceb6f35ac09d0" member_type: VOTER }
I20260812 06:17:32.002785  1312 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:32.002871  1312 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:32.003077  1312 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:32.004415  1312 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1fef819b3fb64861908ceb6f35ac09d0" member_type: VOTER }
I20260812 06:17:32.004999  1312 leader_election.cc:304] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [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: 1fef819b3fb64861908ceb6f35ac09d0; no voters: 
I20260812 06:17:32.005404  1312 leader_election.cc:290] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:32.005645  1317 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:32.005899  1317 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 1 LEADER]: Becoming Leader. State: Replica: 1fef819b3fb64861908ceb6f35ac09d0, State: Running, Role: LEADER
I20260812 06:17:32.006399  1317 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [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: "1fef819b3fb64861908ceb6f35ac09d0" member_type: VOTER }
I20260812 06:17:32.006642  1312 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:32.008503  1320 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1fef819b3fb64861908ceb6f35ac09d0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1fef819b3fb64861908ceb6f35ac09d0" member_type: VOTER } }
I20260812 06:17:32.008546  1321 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1fef819b3fb64861908ceb6f35ac09d0. Latest consensus state: current_term: 1 leader_uuid: "1fef819b3fb64861908ceb6f35ac09d0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1fef819b3fb64861908ceb6f35ac09d0" member_type: VOTER } }
I20260812 06:17:32.008651  1320 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:32.008661  1321 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:32.009057  1334 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:32.009264  1208 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:32.011523  1334 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:32.017304  1334 catalog_manager.cc:1383] Generated new cluster ID: 43ccd631f58f4e739334637cc88c9ec3
I20260812 06:17:32.017405  1334 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:32.032210  1334 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:32.033180  1334 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:32.043541  1334 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0: Generated new TSK 0
I20260812 06:17:32.044468  1334 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:32.074534  1208 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:32.077963  1350 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:32.078078  1351 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:32.078099  1354 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:32.078438  1208 server_base.cc:1061] running on GCE node
I20260812 06:17:32.078670  1208 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:32.078714  1208 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:32.078730  1208 hybrid_clock.cc:648] HybridClock initialized: now 1786515452078730 us; error 0 us; skew 500 ppm
I20260812 06:17:32.079943  1208 webserver.cc:533] Webserver started at http://127.1.46.1:38495/ using document root <none> and password file <none>
I20260812 06:17:32.080179  1208 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:32.080276  1208 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:32.080372  1208 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:32.080803  1208 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/instance:
uuid: "3c8d15d7ae5f49d6979226e90d5c9f78"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-kvfs"
I20260812 06:17:32.082551  1208 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:32.083693  1362 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:32.083971  1208 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:32.084123  1208 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root
uuid: "3c8d15d7ae5f49d6979226e90d5c9f78"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-kvfs"
I20260812 06:17:32.084228  1208 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-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:32.098390  1208 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:32.098941  1208 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:32.099509  1208 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:32.100651  1208 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:32.100720  1208 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.100824  1208 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:32.100885  1208 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.110863  1208 rpc_server.cc:307] RPC server started. Bound to: 127.1.46.1:32989
I20260812 06:17:32.110934  1465 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.46.1:32989 every 8 connection(s)
I20260812 06:17:32.130774  1466 heartbeater.cc:344] Connected to a master server at 127.1.46.62:33417
I20260812 06:17:32.131108  1466 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:32.131675  1466 heartbeater.cc:507] Master 127.1.46.62:33417 requested a full tablet report, sending...
I20260812 06:17:32.133540  1255 ts_manager.cc:194] Registered new tserver with Master: 3c8d15d7ae5f49d6979226e90d5c9f78 (127.1.46.1:32989)
I20260812 06:17:32.133673  1208 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.02192567s
I20260812 06:17:32.135073  1255 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56820
I20260812 06:17:32.145435  1255 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56836:
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:32.163352  1405 tablet_service.cc:1511] Processing CreateTablet for tablet 822d528b8b1e4c4e86f35ce46f77cd53 (DEFAULT_TABLE table=heavy-update-compaction-test [id=faea1226640c40be84fe8ddfd4a2a49b]), partition=
I20260812 06:17:32.163911  1405 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 822d528b8b1e4c4e86f35ce46f77cd53. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:32.167313  1493 tablet_bootstrap.cc:492] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Bootstrap starting.
I20260812 06:17:32.168401  1493 tablet_bootstrap.cc:654] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:32.169696  1493 tablet_bootstrap.cc:492] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: No bootstrap required, opened a new log
I20260812 06:17:32.169832  1493 ts_tablet_manager.cc:1403] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:32.170713  1493 raft_consensus.cc:359] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c8d15d7ae5f49d6979226e90d5c9f78" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 32989 } }
I20260812 06:17:32.170855  1493 raft_consensus.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:32.170904  1493 raft_consensus.cc:740] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3c8d15d7ae5f49d6979226e90d5c9f78, State: Initialized, Role: FOLLOWER
I20260812 06:17:32.171057  1493 consensus_queue.cc:260] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [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: "3c8d15d7ae5f49d6979226e90d5c9f78" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 32989 } }
I20260812 06:17:32.171188  1493 raft_consensus.cc:399] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:32.171243  1493 raft_consensus.cc:493] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:32.171298  1493 raft_consensus.cc:3060] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:32.172214  1493 raft_consensus.cc:515] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c8d15d7ae5f49d6979226e90d5c9f78" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 32989 } }
I20260812 06:17:32.172384  1493 leader_election.cc:304] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [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: 3c8d15d7ae5f49d6979226e90d5c9f78; no voters: 
I20260812 06:17:32.172634  1493 leader_election.cc:290] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:32.172799  1496 raft_consensus.cc:2804] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:32.173023  1493 ts_tablet_manager.cc:1434] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:17:32.173121  1496 raft_consensus.cc:697] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 1 LEADER]: Becoming Leader. State: Replica: 3c8d15d7ae5f49d6979226e90d5c9f78, State: Running, Role: LEADER
I20260812 06:17:32.173261  1466 heartbeater.cc:499] Master 127.1.46.62:33417 was elected leader, sending a full tablet report...
I20260812 06:17:32.173354  1496 consensus_queue.cc:237] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [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: "3c8d15d7ae5f49d6979226e90d5c9f78" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 32989 } }
I20260812 06:17:32.177456  1255 catalog_manager.cc:5719] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3c8d15d7ae5f49d6979226e90d5c9f78 (127.1.46.1). New cstate: current_term: 1 leader_uuid: "3c8d15d7ae5f49d6979226e90d5c9f78" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c8d15d7ae5f49d6979226e90d5c9f78" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 32989 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:32.250419  1208 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.023s	sys 0.007s
I20260812 06:17:32.362414  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=15.086190
I20260812 06:17:32.522409  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.160s	user 0.130s	sys 0.024s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":205,"delete_count":0,"dirs.queue_time_us":140,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":2603,"drs_written":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32957,"lbm_writes_lt_1ms":567,"mutex_wait_us":1144,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":209024,"thread_start_us":135,"threads_started":1,"update_count":1050}
I20260812 06:17:32.523764  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53): free 8725963 bytes of WAL
I20260812 06:17:32.524185  1369 log_reader.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53: removed 1 log segments from log reader
I20260812 06:17:32.524257  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000001 (ops 1-6)
I20260812 06:17:32.526751  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:32.527185  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53): 12308959 bytes on disk
I20260812 06:17:32.527916  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.528499  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:32.543802  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.015s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6086,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.544440  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:32.669871  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.125s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":299,"lbm_read_time_us":8170,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21321,"lbm_writes_lt_1ms":343,"mutex_wait_us":36,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":382,"threads_started":5,"update_count":1500}
I20260812 06:17:32.670488  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:32.720492  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.050s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18309,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.720963  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:32.734127  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.734822  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:32.877703  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.143s	user 0.092s	sys 0.048s 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":388,"lbm_read_time_us":10447,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27762,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2000}
I20260812 06:17:32.878360  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:32.938942  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.060s	user 0.029s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19574,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.939589  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:32.951119  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.951658  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:33.119032  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.167s	user 0.116s	sys 0.044s 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":666,"lbm_read_time_us":11497,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25932,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:17:33.119830  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:33.168262  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.048s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18525,"lbm_writes_lt_1ms":303,"mutex_wait_us":1,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.168810  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:33.183018  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.183712  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:33.317818  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.134s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":10540,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26626,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.318642  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:33.366561  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.048s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16962,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.367105  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:33.380712  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.381462  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:33.528185  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.147s	user 0.110s	sys 0.031s 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":999,"lbm_read_time_us":10138,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27961,"lbm_writes_lt_1ms":443,"mutex_wait_us":357,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:33.530550  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:33.592808  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.062s	user 0.028s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17881,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.593696  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:33.613300  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.019s	user 0.004s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.613976  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:33.770387  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.156s	user 0.123s	sys 0.033s 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":1124,"lbm_read_time_us":12005,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26547,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:17:33.770947  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:33.823863  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.053s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17820,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.824663  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:33.837720  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4698,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.838229  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:33.975049  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.137s	user 0.124s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":10661,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25332,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2000}
I20260812 06:17:33.975638  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:34.020180  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17976,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.020819  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:34.078022  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.057s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":412,"dirs.run_wall_time_us":1846,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2544,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:34.079006  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53): free 127961101 bytes of WAL
I20260812 06:17:34.079304  1369 log_reader.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53: removed 12 log segments from log reader
I20260812 06:17:34.079370  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000002 (ops 7-11)
I20260812 06:17:34.079411  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000003 (ops 12-17)
I20260812 06:17:34.079442  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000004 (ops 18-22)
I20260812 06:17:34.079471  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000005 (ops 23-26)
I20260812 06:17:34.079507  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000006 (ops 27-31)
I20260812 06:17:34.079531  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000007 (ops 32-36)
I20260812 06:17:34.079558  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000008 (ops 37-41)
I20260812 06:17:34.079584  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000009 (ops 42-46)
I20260812 06:17:34.079612  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000010 (ops 47-51)
I20260812 06:17:34.079635  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000011 (ops 52-56)
I20260812 06:17:34.079670  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000012 (ops 57-61)
I20260812 06:17:34.079702  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000013 (ops 62-66)
I20260812 06:17:34.113066  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.034s	user 0.001s	sys 0.032s Metrics: {}
I20260812 06:17:34.113659  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=6.157687
I20260812 06:17:34.145256  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.031s	user 0.027s	sys 0.001s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12270,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:34.145960  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53): free 8767067 bytes of WAL
I20260812 06:17:34.146216  1369 log_reader.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53: removed 1 log segments from log reader
I20260812 06:17:34.146292  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000014 (ops 67-71)
I20260812 06:17:34.148164  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:34.148530  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:34.162933  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.014s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.163475  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:34.359150  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.195s	user 0.137s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836256,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":716,"lbm_read_time_us":12160,"lbm_reads_lt_1ms":665,"lbm_write_time_us":37721,"lbm_writes_lt_1ms":643,"mutex_wait_us":74,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19584,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:17:34.360390  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53): 482 bytes on disk
I20260812 06:17:34.360965  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.361963  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=14.095187
I20260812 06:17:34.412494  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.050s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22839,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.413010  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:34.425573  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.426203  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:34.601634  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.175s	user 0.123s	sys 0.047s 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":1144,"lbm_read_time_us":12551,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32038,"lbm_writes_lt_1ms":543,"mutex_wait_us":389,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":80128,"update_count":2500}
I20260812 06:17:34.602404  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=13.103000
I20260812 06:17:34.655676  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.053s	user 0.024s	sys 0.021s Metrics: {"bytes_written":14768933,"delete_count":0,"lbm_write_time_us":21078,"lbm_writes_lt_1ms":363,"reinsert_count":0,"update_count":1800}
I20260812 06:17:34.656348  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:34.668682  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.012s	user 0.001s	sys 0.006s Metrics: {"bytes_written":2051406,"delete_count":0,"lbm_write_time_us":2249,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:17:34.669194  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:34.681485  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.682204  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:34.889586  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.207s	user 0.143s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733780,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":220,"lbm_read_time_us":10689,"lbm_reads_lt_1ms":573,"lbm_write_time_us":39219,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:34.890254  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=14.095187
I20260812 06:17:34.960353  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.070s	user 0.024s	sys 0.035s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26175,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.961195  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:34.973551  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.974455  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:35.156837  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.182s	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":159,"lbm_read_time_us":12832,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31655,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2500}
I20260812 06:17:35.157523  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=14.095187
I20260812 06:17:35.230077  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.072s	user 0.043s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26257,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.230764  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:35.243373  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4497,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.244118  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:35.456990  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.213s	user 0.149s	sys 0.054s 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":803,"lbm_read_time_us":16700,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35149,"lbm_writes_lt_1ms":543,"mutex_wait_us":406,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:35.457952  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:35.509686  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.051s	user 0.029s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22238,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.510294  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:35.542539  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.032s	user 0.008s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.543777  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:35.706359  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.162s	user 0.125s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":442,"lbm_read_time_us":13671,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24654,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:17:35.706995  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:35.751413  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.044s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19396,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.751929  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:35.768277  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.768847  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:35.801820  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1778,"drs_written":1,"lbm_read_time_us":131,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2154,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:35.803220  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53): free 121006504 bytes of WAL
I20260812 06:17:35.803617  1369 log_reader.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53: removed 12 log segments from log reader
I20260812 06:17:35.803694  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000015 (ops 72-76)
I20260812 06:17:35.803754  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000016 (ops 77-81)
I20260812 06:17:35.803798  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000017 (ops 82-86)
I20260812 06:17:35.803840  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000018 (ops 87-91)
I20260812 06:17:35.803885  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000019 (ops 92-96)
I20260812 06:17:35.803926  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000020 (ops 97-101)
I20260812 06:17:35.803977  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000021 (ops 102-106)
I20260812 06:17:35.804047  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000022 (ops 107-111)
I20260812 06:17:35.804086  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000023 (ops 112-116)
I20260812 06:17:35.804118  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000024 (ops 117-120)
I20260812 06:17:35.804159  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000025 (ops 121-125)
I20260812 06:17:35.804193  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000026 (ops 126-130)
I20260812 06:17:35.836571  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:35.837080  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53): 483 bytes on disk
I20260812 06:17:35.837531  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53) 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:35.838053  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=6.157687
I20260812 06:17:35.863497  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.025s	user 0.011s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10690,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:35.864212  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53): free 11564893 bytes of WAL
I20260812 06:17:35.864552  1369 log_reader.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53: removed 1 log segments from log reader
I20260812 06:17:35.864673  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000027 (ops 131-134)
I20260812 06:17:35.867003  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:35.867398  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:36.048170  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.180s	user 0.156s	sys 0.024s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836256,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":317,"lbm_read_time_us":13767,"lbm_reads_lt_1ms":665,"lbm_write_time_us":36591,"lbm_writes_lt_1ms":643,"mutex_wait_us":304,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18304,"thread_start_us":126,"threads_started":1,"update_count":3000}
I20260812 06:17:36.048995  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=14.095187
I20260812 06:17:36.104079  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.055s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23975,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.104681  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:36.118597  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.119175  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:36.296989  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.178s	user 0.127s	sys 0.047s 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":561,"lbm_read_time_us":11637,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35497,"lbm_writes_lt_1ms":543,"mutex_wait_us":280,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:36.297703  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=11.118625
I20260812 06:17:36.339437  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17282,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.343423  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:36.365365  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.022s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.366034  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:36.379736  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4487,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.380339  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:36.533512  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.153s	user 0.124s	sys 0.029s 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":340,"lbm_read_time_us":10890,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31634,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:17:36.534400  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=11.118625
I20260812 06:17:36.569840  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.035s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15220,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.570516  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:36.592361  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.022s	user 0.009s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":8057,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.592938  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:36.717542  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.124s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":737,"lbm_read_time_us":7857,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24442,"lbm_writes_lt_1ms":443,"mutex_wait_us":460,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:36.718254  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:36.754374  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.036s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15608,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.755016  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:36.773321  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6574,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.774045  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:36.929987  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.156s	user 0.131s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":946,"lbm_read_time_us":10140,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30788,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:17:36.930859  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:36.983978  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.053s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15998,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.984622  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:36.997710  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.998250  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:37.164964  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.167s	user 0.141s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":423,"lbm_read_time_us":12244,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26777,"lbm_writes_lt_1ms":443,"mutex_wait_us":100,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:37.165766  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:37.225256  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.059s	user 0.033s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21973,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.225874  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:37.239051  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.239948  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:37.390791  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.150s	user 0.101s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1253,"lbm_read_time_us":10197,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29332,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":46592,"update_count":2000}
I20260812 06:17:37.391798  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=10.126437
I20260812 06:17:37.441859  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.050s	user 0.015s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20315,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.442639  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:37.462697  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.020s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.463600  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:37.511984  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushMRSOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.048s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1397,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1833,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:37.512820  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=3.181125
I20260812 06:17:37.527486  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5226,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:37.528126  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53): free 129320724 bytes of WAL
I20260812 06:17:37.528368  1369 log_reader.cc:385] T 822d528b8b1e4c4e86f35ce46f77cd53: removed 13 log segments from log reader
I20260812 06:17:37.528414  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000028 (ops 135-139)
I20260812 06:17:37.528450  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000029 (ops 140-144)
I20260812 06:17:37.528529  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000030 (ops 145-149)
I20260812 06:17:37.528594  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000031 (ops 150-154)
I20260812 06:17:37.528641  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000032 (ops 155-158)
I20260812 06:17:37.528687  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000033 (ops 159-163)
I20260812 06:17:37.528734  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000034 (ops 164-168)
I20260812 06:17:37.528779  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000035 (ops 169-172)
I20260812 06:17:37.528822  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000036 (ops 173-177)
I20260812 06:17:37.528865  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000037 (ops 178-182)
I20260812 06:17:37.528909  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000038 (ops 183-187)
I20260812 06:17:37.528952  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000039 (ops 188-192)
I20260812 06:17:37.528996  1369 log.cc:1079] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/822d528b8b1e4c4e86f35ce46f77cd53/wal-000000040 (ops 193-197)
I20260812 06:17:37.564146  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: LogGCOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.036s	user 0.004s	sys 0.032s Metrics: {}
I20260812 06:17:37.564666  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53): 492 bytes on disk
I20260812 06:17:37.565146  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: UndoDeltaBlockGCOp(822d528b8b1e4c4e86f35ce46f77cd53) 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:37.565718  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:37.579188  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4740,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.579712  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=2.188937
I20260812 06:17:37.590904  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: FlushDeltaMemStoresOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.591387  1467 maintenance_manager.cc:419] P 3c8d15d7ae5f49d6979226e90d5c9f78: Scheduling MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53): perf score=1.000000
I20260812 06:17:37.631712  1208 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.381s	user 1.980s	sys 0.122s
I20260812 06:17:37.750931  1208 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.119s	user 0.001s	sys 0.000s
I20260812 06:17:37.751634  1208 tablet_server.cc:179] TabletServer@127.1.46.1:0 shutting down...
I20260812 06:17:37.789743  1369 maintenance_manager.cc:643] P 3c8d15d7ae5f49d6979226e90d5c9f78: MajorDeltaCompactionOp(822d528b8b1e4c4e86f35ce46f77cd53) complete. Timing: real 0.198s	user 0.138s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938892,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":603,"lbm_read_time_us":17330,"lbm_reads_lt_1ms":771,"lbm_write_time_us":35297,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":106,"threads_started":1,"update_count":3500}
I20260812 06:17:37.790592  1208 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:37.791201  1208 tablet_replica.cc:333] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78: stopping tablet replica
I20260812 06:17:37.791477  1208 raft_consensus.cc:2243] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.791731  1208 raft_consensus.cc:2272] T 822d528b8b1e4c4e86f35ce46f77cd53 P 3c8d15d7ae5f49d6979226e90d5c9f78 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.809947  1208 tablet_server.cc:196] TabletServer@127.1.46.1:0 shutdown complete.
I20260812 06:17:37.848496  1208 master.cc:562] Master@127.1.46.62:33417 shutting down...
I20260812 06:17:37.853797  1208 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.854003  1208 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.854084  1208 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1fef819b3fb64861908ceb6f35ac09d0: stopping tablet replica
I20260812 06:17:37.867113  1208 master.cc:584] Master@127.1.46.62:33417 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6042 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:37.961884  1208 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.46.62:34367
I20260812 06:17:37.962291  1208 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:37.964427  1525 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:37.964577  1530 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:37.964613  1208 server_base.cc:1061] running on GCE node
W20260812 06:17:37.964582  1522 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:37.964927  1208 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:37.964977  1208 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:37.964991  1208 hybrid_clock.cc:648] HybridClock initialized: now 1786515457964991 us; error 0 us; skew 500 ppm
I20260812 06:17:37.965874  1208 webserver.cc:533] Webserver started at http://127.1.46.62:46119/ using document root <none> and password file <none>
I20260812 06:17:37.966058  1208 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:37.966126  1208 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:37.966221  1208 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:37.966636  1208 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/master-0-root/instance:
uuid: "c5bf076d021d4f27b48d5955a909ee2b"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-kvfs"
I20260812 06:17:37.968287  1208 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:37.969357  1537 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:37.969633  1208 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:37.969735  1208 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/master-0-root
uuid: "c5bf076d021d4f27b48d5955a909ee2b"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-kvfs"
I20260812 06:17:37.969831  1208 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-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:38.005313  1208 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.005805  1208 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.011034  1208 rpc_server.cc:307] RPC server started. Bound to: 127.1.46.62:34367
I20260812 06:17:38.014816  1628 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:38.017128  1627 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.46.62:34367 every 8 connection(s)
I20260812 06:17:38.032374  1628 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b: Bootstrap starting.
I20260812 06:17:38.033495  1628 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.035046  1628 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b: No bootstrap required, opened a new log
I20260812 06:17:38.035514  1628 raft_consensus.cc:359] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bf076d021d4f27b48d5955a909ee2b" member_type: VOTER }
I20260812 06:17:38.035617  1628 raft_consensus.cc:385] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.035641  1628 raft_consensus.cc:740] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c5bf076d021d4f27b48d5955a909ee2b, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.035827  1628 consensus_queue.cc:260] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [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: "c5bf076d021d4f27b48d5955a909ee2b" member_type: VOTER }
I20260812 06:17:38.035939  1628 raft_consensus.cc:399] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.035969  1628 raft_consensus.cc:493] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.036000  1628 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.037189  1628 raft_consensus.cc:515] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bf076d021d4f27b48d5955a909ee2b" member_type: VOTER }
I20260812 06:17:38.037386  1628 leader_election.cc:304] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [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: c5bf076d021d4f27b48d5955a909ee2b; no voters: 
I20260812 06:17:38.037622  1628 leader_election.cc:290] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.037755  1633 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.037925  1633 raft_consensus.cc:697] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 1 LEADER]: Becoming Leader. State: Replica: c5bf076d021d4f27b48d5955a909ee2b, State: Running, Role: LEADER
I20260812 06:17:38.038156  1633 consensus_queue.cc:237] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [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: "c5bf076d021d4f27b48d5955a909ee2b" member_type: VOTER }
I20260812 06:17:38.038237  1628 sys_catalog.cc:565] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:38.038733  1634 sys_catalog.cc:455] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c5bf076d021d4f27b48d5955a909ee2b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bf076d021d4f27b48d5955a909ee2b" member_type: VOTER } }
I20260812 06:17:38.038795  1636 sys_catalog.cc:455] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [sys.catalog]: SysCatalogTable state changed. Reason: New leader c5bf076d021d4f27b48d5955a909ee2b. Latest consensus state: current_term: 1 leader_uuid: "c5bf076d021d4f27b48d5955a909ee2b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bf076d021d4f27b48d5955a909ee2b" member_type: VOTER } }
I20260812 06:17:38.038920  1634 sys_catalog.cc:458] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.038944  1636 sys_catalog.cc:458] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.039309  1640 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:38.040282  1640 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:38.040530  1208 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:38.042325  1640 catalog_manager.cc:1383] Generated new cluster ID: 0508ad37325244fa839f594ec59fb650
I20260812 06:17:38.042387  1640 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:38.064144  1640 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:38.064713  1640 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:38.074878  1640 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b: Generated new TSK 0
I20260812 06:17:38.075102  1640 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:38.105831  1208 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:38.108269  1660 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:38.108314  1208 server_base.cc:1061] running on GCE node
W20260812 06:17:38.108318  1661 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:38.108307  1663 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:38.108760  1208 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.108812  1208 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:38.108832  1208 hybrid_clock.cc:648] HybridClock initialized: now 1786515458108832 us; error 0 us; skew 500 ppm
I20260812 06:17:38.109838  1208 webserver.cc:533] Webserver started at http://127.1.46.1:46125/ using document root <none> and password file <none>
I20260812 06:17:38.110038  1208 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.110095  1208 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.110200  1208 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.110631  1208 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/instance:
uuid: "3106529f102a4fe7a2a33b059ec1b4c5"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-kvfs"
I20260812 06:17:38.112637  1208 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:38.113881  1671 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:38.114214  1208 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:38.114317  1208 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root
uuid: "3106529f102a4fe7a2a33b059ec1b4c5"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-kvfs"
I20260812 06:17:38.114430  1208 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-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:38.130818  1208 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.131593  1208 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.132284  1208 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:38.132915  1208 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:38.132987  1208 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.133049  1208 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:38.133107  1208 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.138401  1208 rpc_server.cc:307] RPC server started. Bound to: 127.1.46.1:35159
I20260812 06:17:38.138469  1778 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.46.1:35159 every 8 connection(s)
I20260812 06:17:38.148089  1779 heartbeater.cc:344] Connected to a master server at 127.1.46.62:34367
I20260812 06:17:38.148249  1779 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:38.148579  1779 heartbeater.cc:507] Master 127.1.46.62:34367 requested a full tablet report, sending...
I20260812 06:17:38.149497  1568 ts_manager.cc:194] Registered new tserver with Master: 3106529f102a4fe7a2a33b059ec1b4c5 (127.1.46.1:35159)
I20260812 06:17:38.150296  1568 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40932
I20260812 06:17:38.150424  1208 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011506703s
I20260812 06:17:38.159608  1568 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40948:
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:38.170352  1716 tablet_service.cc:1511] Processing CreateTablet for tablet 751bba1ea8394ab180c0517706544f7c (DEFAULT_TABLE table=heavy-update-compaction-test [id=ec704273cc8d4d8da9319024f2a11c79]), partition=
I20260812 06:17:38.170732  1716 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 751bba1ea8394ab180c0517706544f7c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:38.173205  1796 tablet_bootstrap.cc:492] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Bootstrap starting.
I20260812 06:17:38.174363  1796 tablet_bootstrap.cc:654] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.175974  1796 tablet_bootstrap.cc:492] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: No bootstrap required, opened a new log
I20260812 06:17:38.176146  1796 ts_tablet_manager.cc:1403] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:38.176623  1796 raft_consensus.cc:359] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3106529f102a4fe7a2a33b059ec1b4c5" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 35159 } }
I20260812 06:17:38.176752  1796 raft_consensus.cc:385] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.176793  1796 raft_consensus.cc:740] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3106529f102a4fe7a2a33b059ec1b4c5, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.176967  1796 consensus_queue.cc:260] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [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: "3106529f102a4fe7a2a33b059ec1b4c5" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 35159 } }
I20260812 06:17:38.177265  1796 raft_consensus.cc:399] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.177350  1796 raft_consensus.cc:493] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.177414  1796 raft_consensus.cc:3060] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.178277  1796 raft_consensus.cc:515] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3106529f102a4fe7a2a33b059ec1b4c5" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 35159 } }
I20260812 06:17:38.178452  1796 leader_election.cc:304] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [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: 3106529f102a4fe7a2a33b059ec1b4c5; no voters: 
I20260812 06:17:38.178701  1796 leader_election.cc:290] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.178887  1799 raft_consensus.cc:2804] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.179252  1796 ts_tablet_manager.cc:1434] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:38.179283  1779 heartbeater.cc:499] Master 127.1.46.62:34367 was elected leader, sending a full tablet report...
I20260812 06:17:38.179157  1799 raft_consensus.cc:697] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 1 LEADER]: Becoming Leader. State: Replica: 3106529f102a4fe7a2a33b059ec1b4c5, State: Running, Role: LEADER
I20260812 06:17:38.179647  1799 consensus_queue.cc:237] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [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: "3106529f102a4fe7a2a33b059ec1b4c5" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 35159 } }
I20260812 06:17:38.181211  1568 catalog_manager.cc:5719] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3106529f102a4fe7a2a33b059ec1b4c5 (127.1.46.1). New cstate: current_term: 1 leader_uuid: "3106529f102a4fe7a2a33b059ec1b4c5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3106529f102a4fe7a2a33b059ec1b4c5" member_type: VOTER last_known_addr { host: "127.1.46.1" port: 35159 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:38.244488  1208 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.021s	sys 0.003s
I20260812 06:17:38.389454  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushMRSOp(751bba1ea8394ab180c0517706544f7c): perf score=19.054940
I20260812 06:17:38.563653  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushMRSOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.174s	user 0.121s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":929,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42370,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:38.564486  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling LogGCOp(751bba1ea8394ab180c0517706544f7c): free 20290830 bytes of WAL
I20260812 06:17:38.564767  1677 log_reader.cc:385] T 751bba1ea8394ab180c0517706544f7c: removed 2 log segments from log reader
I20260812 06:17:38.564841  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000001 (ops 1-6)
I20260812 06:17:38.564886  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000002 (ops 7-10)
I20260812 06:17:38.571321  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: LogGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.007s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:38.571883  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:38.594017  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.594617  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c): 16411395 bytes on disk
I20260812 06:17:38.595055  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c) 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:38.595446  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:38.754812  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.159s	user 0.096s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1791,"lbm_read_time_us":11103,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25019,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"thread_start_us":742,"threads_started":5,"update_count":2000}
I20260812 06:17:38.757089  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:38.838146  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.081s	user 0.062s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":36964,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.838708  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:38.857160  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6545,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.857851  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:39.077381  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.219s	user 0.155s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":910,"lbm_read_time_us":13291,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39286,"lbm_writes_lt_1ms":543,"mutex_wait_us":374,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":64512,"update_count":2500}
I20260812 06:17:39.078044  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:39.130837  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.053s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22355,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.131335  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:39.314492  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.183s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":294,"lbm_read_time_us":9917,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28633,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:17:39.315138  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:39.373878  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.059s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23382,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.374402  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:39.388496  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.389137  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:39.616878  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.228s	user 0.157s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":17091,"lbm_reads_lt_1ms":572,"lbm_write_time_us":46994,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:39.617743  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:39.675698  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.057s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25499,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.676702  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:39.693810  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.694438  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:39.860003  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.165s	user 0.118s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":932,"lbm_read_time_us":10461,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33243,"lbm_writes_lt_1ms":543,"mutex_wait_us":448,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:39.860790  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=11.118625
I20260812 06:17:39.894742  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.034s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14461,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.895874  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:39.919044  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.023s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7314,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.919713  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushMRSOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:39.966442  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushMRSOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.046s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":356,"dirs.run_wall_time_us":1644,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1860,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:39.967546  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=3.181125
I20260812 06:17:39.981071  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:39.981773  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling LogGCOp(751bba1ea8394ab180c0517706544f7c): free 108535388 bytes of WAL
I20260812 06:17:39.982040  1677 log_reader.cc:385] T 751bba1ea8394ab180c0517706544f7c: removed 11 log segments from log reader
I20260812 06:17:39.982091  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000003 (ops 11-15)
I20260812 06:17:39.982126  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000004 (ops 16-20)
I20260812 06:17:39.982198  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000005 (ops 21-25)
I20260812 06:17:39.982249  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000006 (ops 26-30)
I20260812 06:17:39.982298  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000007 (ops 31-34)
I20260812 06:17:39.982357  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000008 (ops 35-39)
I20260812 06:17:39.982403  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000009 (ops 40-44)
I20260812 06:17:39.982451  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000010 (ops 45-49)
I20260812 06:17:39.982618  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000011 (ops 50-54)
I20260812 06:17:39.982712  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000012 (ops 55-58)
I20260812 06:17:39.982776  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000013 (ops 59-63)
I20260812 06:17:40.011135  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: LogGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:40.011560  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c): 447 bytes on disk
I20260812 06:17:40.012006  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:40.012720  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:40.037071  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.024s	user 0.002s	sys 0.018s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.037680  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:40.048666  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:40.049430  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:40.328423  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.279s	user 0.161s	sys 0.116s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":992,"lbm_read_time_us":18615,"lbm_reads_lt_1ms":775,"lbm_write_time_us":46824,"lbm_writes_lt_1ms":743,"mutex_wait_us":315,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":130,"threads_started":1,"update_count":3500}
I20260812 06:17:40.329207  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:40.400233  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.070s	user 0.041s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27899,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.401031  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:40.423113  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.022s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.423646  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:40.616876  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.193s	user 0.125s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1059,"lbm_read_time_us":13924,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31997,"lbm_writes_lt_1ms":543,"mutex_wait_us":347,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:17:40.617420  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:40.682188  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.064s	user 0.027s	sys 0.035s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":23068,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.682825  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:40.693946  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.694557  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:40.891003  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.196s	user 0.131s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":628,"lbm_read_time_us":13907,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31227,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":76800,"update_count":2500}
I20260812 06:17:40.891714  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=11.118625
I20260812 06:17:40.940526  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.049s	user 0.037s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19855,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:40.941552  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:40.983176  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.041s	user 0.011s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:40.983879  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:40.996220  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.996997  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:41.185696  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.188s	user 0.128s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":430,"lbm_read_time_us":15133,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32246,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:41.186305  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=10.126437
I20260812 06:17:41.239015  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.052s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22942,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.239647  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:41.262550  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.023s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":81280,"update_count":500}
I20260812 06:17:41.263154  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:41.416376  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.153s	user 0.126s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":714,"lbm_read_time_us":9464,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29797,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:41.417194  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=11.118625
I20260812 06:17:41.457460  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.038s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16649,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:41.458066  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:41.483114  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5925,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:41.483639  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:41.641075  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.157s	user 0.117s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1588,"lbm_read_time_us":8944,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28151,"lbm_writes_lt_1ms":443,"mutex_wait_us":391,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:41.641585  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:41.696277  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.055s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23783,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.697127  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:41.711007  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.711616  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushMRSOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:41.747078  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushMRSOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.035s	user 0.026s	sys 0.007s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":2212,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2289,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:41.747901  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling LogGCOp(751bba1ea8394ab180c0517706544f7c): free 133024364 bytes of WAL
I20260812 06:17:41.748202  1677 log_reader.cc:385] T 751bba1ea8394ab180c0517706544f7c: removed 13 log segments from log reader
I20260812 06:17:41.748275  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000014 (ops 64-68)
I20260812 06:17:41.748318  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000015 (ops 69-73)
I20260812 06:17:41.748350  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000016 (ops 74-78)
I20260812 06:17:41.748373  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000017 (ops 79-83)
I20260812 06:17:41.748406  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000018 (ops 84-88)
I20260812 06:17:41.748440  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000019 (ops 89-93)
I20260812 06:17:41.748463  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000020 (ops 94-98)
I20260812 06:17:41.748492  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000021 (ops 99-103)
I20260812 06:17:41.748522  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000022 (ops 104-108)
I20260812 06:17:41.748551  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000023 (ops 109-113)
I20260812 06:17:41.748605  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000024 (ops 114-118)
I20260812 06:17:41.748638  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000025 (ops 119-122)
I20260812 06:17:41.748667  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000026 (ops 123-127)
I20260812 06:17:41.782905  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: LogGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.035s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:41.783515  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=3.181125
I20260812 06:17:41.800113  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5441,"lbm_writes_lt_1ms":113,"mutex_wait_us":1,"reinsert_count":0,"update_count":550}
I20260812 06:17:41.800670  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:41.810716  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3664,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:41.811192  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:42.026081  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.215s	user 0.166s	sys 0.048s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":753,"lbm_read_time_us":17736,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42820,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:17:42.026907  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:42.086297  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.059s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25245,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.087504  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c): 472 bytes on disk
I20260812 06:17:42.088243  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":115,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.089054  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:42.116626  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.027s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5630,"lbm_writes_lt_1ms":103,"mutex_wait_us":3,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.117128  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:42.129726  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.130522  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:42.322620  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.190s	user 0.137s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1767,"lbm_read_time_us":15531,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37025,"lbm_writes_lt_1ms":643,"mutex_wait_us":693,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":3000}
I20260812 06:17:42.323540  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:42.376857  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.053s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24111,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.377653  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:42.397727  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.398228  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:42.408882  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.409343  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:42.582841  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.173s	user 0.139s	sys 0.034s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1030,"lbm_read_time_us":11783,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37092,"lbm_writes_lt_1ms":643,"mutex_wait_us":361,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:17:42.583562  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:42.638305  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.055s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24268,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.638854  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:42.651762  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.652455  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:42.831334  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.179s	user 0.109s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":834,"lbm_read_time_us":11585,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33488,"lbm_writes_lt_1ms":543,"mutex_wait_us":388,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:42.832268  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:42.884680  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.052s	user 0.043s	sys 0.009s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.885562  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:43.068979  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.183s	user 0.111s	sys 0.059s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":560,"lbm_read_time_us":11363,"lbm_reads_lt_1ms":463,"lbm_write_time_us":30728,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:43.069617  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=14.095187
I20260812 06:17:43.123514  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.054s	user 0.036s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18674,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.124173  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:43.138075  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.138772  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushMRSOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:43.176985  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushMRSOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.038s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1312,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2232,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1792}
I20260812 06:17:43.177750  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling LogGCOp(751bba1ea8394ab180c0517706544f7c): free 112239548 bytes of WAL
I20260812 06:17:43.177981  1677 log_reader.cc:385] T 751bba1ea8394ab180c0517706544f7c: removed 11 log segments from log reader
I20260812 06:17:43.178027  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000027 (ops 128-132)
I20260812 06:17:43.178058  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000028 (ops 133-137)
I20260812 06:17:43.178125  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000029 (ops 138-142)
I20260812 06:17:43.178171  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000030 (ops 143-147)
I20260812 06:17:43.178213  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000031 (ops 148-152)
I20260812 06:17:43.178264  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000032 (ops 153-157)
I20260812 06:17:43.178303  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000033 (ops 158-162)
I20260812 06:17:43.178342  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000034 (ops 163-166)
I20260812 06:17:43.178377  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000035 (ops 167-171)
I20260812 06:17:43.178419  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000036 (ops 172-176)
I20260812 06:17:43.178455  1677 log.cc:1079] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: Deleting log segment in path: /tmp/dist-test-task2RcPys/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515451907916-1208-0/minicluster-data/ts-0-root/wals/751bba1ea8394ab180c0517706544f7c/wal-000000037 (ops 177-181)
I20260812 06:17:43.205888  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: LogGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:43.206369  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=3.181125
I20260812 06:17:43.234900  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.028s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6295,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:43.235543  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c): 448 bytes on disk
I20260812 06:17:43.236315  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: UndoDeltaBlockGCOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":158,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.236864  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:43.250844  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.014s	user 0.010s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5064,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.251628  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:43.496622  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.244s	user 0.172s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":577,"lbm_read_time_us":18104,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39432,"lbm_writes_lt_1ms":743,"mutex_wait_us":92,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":31104,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:17:43.497466  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=15.087375
I20260812 06:17:43.550012  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.052s	user 0.037s	sys 0.013s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":22339,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:43.550788  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=2.188937
I20260812 06:17:43.572206  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.021s	user 0.010s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6745,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.572793  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c): perf score=1.000000
I20260812 06:17:43.701068  1208 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.456s	user 2.073s	sys 0.149s
I20260812 06:17:43.752734  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: MajorDeltaCompactionOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.180s	user 0.123s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774674,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":12351,"lbm_reads_lt_1ms":560,"lbm_write_time_us":30498,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:17:43.753535  1780 maintenance_manager.cc:419] P 3106529f102a4fe7a2a33b059ec1b4c5: Scheduling FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c): perf score=10.126437
I20260812 06:17:43.764218  1208 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.003s	sys 0.000s
I20260812 06:17:43.764766  1208 tablet_server.cc:179] TabletServer@127.1.46.1:0 shutting down...
I20260812 06:17:43.794092  1677 maintenance_manager.cc:643] P 3106529f102a4fe7a2a33b059ec1b4c5: FlushDeltaMemStoresOp(751bba1ea8394ab180c0517706544f7c) complete. Timing: real 0.040s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16880,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.794838  1208 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:43.795254  1208 tablet_replica.cc:333] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5: stopping tablet replica
I20260812 06:17:43.795423  1208 raft_consensus.cc:2243] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:43.795621  1208 raft_consensus.cc:2272] T 751bba1ea8394ab180c0517706544f7c P 3106529f102a4fe7a2a33b059ec1b4c5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:43.811532  1208 tablet_server.cc:196] TabletServer@127.1.46.1:0 shutdown complete.
I20260812 06:17:43.816614  1208 master.cc:562] Master@127.1.46.62:34367 shutting down...
I20260812 06:17:43.822388  1208 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:43.822685  1208 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:43.822793  1208 tablet_replica.cc:333] T 00000000000000000000000000000000 P c5bf076d021d4f27b48d5955a909ee2b: stopping tablet replica
I20260812 06:17:43.835815  1208 master.cc:584] Master@127.1.46.62:34367 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5970 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12014 ms total)

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