[==========] 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:19:36.104259 30707 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.252.254:46241
I20260812 06:19:36.105294 30707 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:19:36.105979 30707 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.112962 30725 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:36.113088 30723 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:19:36.113284 30720 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:19:36.113314 30707 server_base.cc:1061] running on GCE node
I20260812 06:19:36.114187 30707 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.114316 30707 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:19:36.114351 30707 hybrid_clock.cc:648] HybridClock initialized: now 1786515576114348 us; error 0 us; skew 500 ppm
I20260812 06:19:36.116786 30707 webserver.cc:533] Webserver started at http://127.29.252.254:42719/ using document root <none> and password file <none>
I20260812 06:19:36.117498 30707 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.117568 30707 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.117889 30707 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.119966 30707 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/master-0-root/instance:
uuid: "777f750d83fd4ea890cb1ec3932935ca"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-t7g5"
I20260812 06:19:36.124392 30707 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.000s
I20260812 06:19:36.127151 30736 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:19:36.128664 30707 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:36.128823 30707 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/master-0-root
uuid: "777f750d83fd4ea890cb1ec3932935ca"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-t7g5"
I20260812 06:19:36.128955 30707 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-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:19:36.154171 30707 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.155360 30707 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:19:36.155596 30707 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.164945 30821 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.252.254:46241 every 8 connection(s)
I20260812 06:19:36.164947 30707 rpc_server.cc:307] RPC server started. Bound to: 127.29.252.254:46241
I20260812 06:19:36.167532 30823 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:19:36.173692 30823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: Bootstrap starting.
I20260812 06:19:36.176332 30823 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.177992 30823 log.cc:826] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:36.180672 30823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: No bootstrap required, opened a new log
I20260812 06:19:36.183859 30823 raft_consensus.cc:359] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "777f750d83fd4ea890cb1ec3932935ca" member_type: VOTER }
I20260812 06:19:36.184073 30823 raft_consensus.cc:385] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.184115 30823 raft_consensus.cc:740] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 777f750d83fd4ea890cb1ec3932935ca, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.184767 30823 consensus_queue.cc:260] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [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: "777f750d83fd4ea890cb1ec3932935ca" member_type: VOTER }
I20260812 06:19:36.184924 30823 raft_consensus.cc:399] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.184984 30823 raft_consensus.cc:493] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.185115 30823 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.186061 30823 raft_consensus.cc:515] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "777f750d83fd4ea890cb1ec3932935ca" member_type: VOTER }
I20260812 06:19:36.186555 30823 leader_election.cc:304] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [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: 777f750d83fd4ea890cb1ec3932935ca; no voters: 
I20260812 06:19:36.186945 30823 leader_election.cc:290] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.187132 30829 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.187366 30829 raft_consensus.cc:697] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 1 LEADER]: Becoming Leader. State: Replica: 777f750d83fd4ea890cb1ec3932935ca, State: Running, Role: LEADER
I20260812 06:19:36.187765 30829 consensus_queue.cc:237] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [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: "777f750d83fd4ea890cb1ec3932935ca" member_type: VOTER }
I20260812 06:19:36.188074 30823 sys_catalog.cc:565] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:36.189850 30832 sys_catalog.cc:455] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [sys.catalog]: SysCatalogTable state changed. Reason: New leader 777f750d83fd4ea890cb1ec3932935ca. Latest consensus state: current_term: 1 leader_uuid: "777f750d83fd4ea890cb1ec3932935ca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "777f750d83fd4ea890cb1ec3932935ca" member_type: VOTER } }
I20260812 06:19:36.189999 30832 sys_catalog.cc:458] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.190358 30830 sys_catalog.cc:455] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "777f750d83fd4ea890cb1ec3932935ca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "777f750d83fd4ea890cb1ec3932935ca" member_type: VOTER } }
I20260812 06:19:36.190455 30830 sys_catalog.cc:458] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.190534 30707 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:36.192659 30850 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:36.192737 30850 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:36.192803 30846 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:36.193526 30846 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:36.199476 30846 catalog_manager.cc:1383] Generated new cluster ID: 42e2a7187ecd418fbc73b9f3b54de3ec
I20260812 06:19:36.199607 30846 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:36.219393 30846 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:36.220541 30846 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:36.231128 30846 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: Generated new TSK 0
I20260812 06:19:36.232218 30846 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:36.259205 30707 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.262578 30857 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:19:36.262616 30855 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:19:36.262807 30859 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:19:36.263437 30707 server_base.cc:1061] running on GCE node
I20260812 06:19:36.263700 30707 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.263751 30707 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:19:36.263770 30707 hybrid_clock.cc:648] HybridClock initialized: now 1786515576263770 us; error 0 us; skew 500 ppm
I20260812 06:19:36.264823 30707 webserver.cc:533] Webserver started at http://127.29.252.193:34957/ using document root <none> and password file <none>
I20260812 06:19:36.265009 30707 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.265074 30707 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.265292 30707 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.265946 30707 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/instance:
uuid: "ef853ddf72fa4cdb8ad577a97e0ad5ed"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-t7g5"
I20260812 06:19:36.267654 30707 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:36.268702 30865 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:19:36.268999 30707 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:36.269073 30707 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root
uuid: "ef853ddf72fa4cdb8ad577a97e0ad5ed"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-t7g5"
I20260812 06:19:36.269135 30707 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-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:19:36.276139 30707 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.276659 30707 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.277150 30707 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:36.278066 30707 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:36.278123 30707 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.278167 30707 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:36.278182 30707 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.285156 30707 rpc_server.cc:307] RPC server started. Bound to: 127.29.252.193:42009
I20260812 06:19:36.285169 30969 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.252.193:42009 every 8 connection(s)
I20260812 06:19:36.298789 30970 heartbeater.cc:344] Connected to a master server at 127.29.252.254:46241
I20260812 06:19:36.299124 30970 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:36.299683 30970 heartbeater.cc:507] Master 127.29.252.254:46241 requested a full tablet report, sending...
I20260812 06:19:36.301602 30764 ts_manager.cc:194] Registered new tserver with Master: ef853ddf72fa4cdb8ad577a97e0ad5ed (127.29.252.193:42009)
I20260812 06:19:36.301745 30707 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015873745s
I20260812 06:19:36.303294 30764 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60640
I20260812 06:19:36.314047 30764 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60644:
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:19:36.331985 30907 tablet_service.cc:1511] Processing CreateTablet for tablet 6e9f36b213d342cf8dbfbadf05f7ccd7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f4a5e82684c94ebe829e436479b21137]), partition=
I20260812 06:19:36.332623 30907 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6e9f36b213d342cf8dbfbadf05f7ccd7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:36.335937 30999 tablet_bootstrap.cc:492] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Bootstrap starting.
I20260812 06:19:36.337191 30999 tablet_bootstrap.cc:654] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.338711 30999 tablet_bootstrap.cc:492] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: No bootstrap required, opened a new log
I20260812 06:19:36.338827 30999 ts_tablet_manager.cc:1403] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:36.339352 30999 raft_consensus.cc:359] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ef853ddf72fa4cdb8ad577a97e0ad5ed" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 42009 } }
I20260812 06:19:36.339479 30999 raft_consensus.cc:385] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.339504 30999 raft_consensus.cc:740] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ef853ddf72fa4cdb8ad577a97e0ad5ed, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.339623 30999 consensus_queue.cc:260] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [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: "ef853ddf72fa4cdb8ad577a97e0ad5ed" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 42009 } }
I20260812 06:19:36.339718 30999 raft_consensus.cc:399] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.339758 30999 raft_consensus.cc:493] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.339811 30999 raft_consensus.cc:3060] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.340742 30999 raft_consensus.cc:515] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ef853ddf72fa4cdb8ad577a97e0ad5ed" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 42009 } }
I20260812 06:19:36.340907 30999 leader_election.cc:304] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [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: ef853ddf72fa4cdb8ad577a97e0ad5ed; no voters: 
I20260812 06:19:36.341145 30999 leader_election.cc:290] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.341531 31002 raft_consensus.cc:2804] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.341625 30999 ts_tablet_manager.cc:1434] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:36.342083 30970 heartbeater.cc:499] Master 127.29.252.254:46241 was elected leader, sending a full tablet report...
I20260812 06:19:36.342422 31002 raft_consensus.cc:697] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 1 LEADER]: Becoming Leader. State: Replica: ef853ddf72fa4cdb8ad577a97e0ad5ed, State: Running, Role: LEADER
I20260812 06:19:36.342655 31002 consensus_queue.cc:237] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [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: "ef853ddf72fa4cdb8ad577a97e0ad5ed" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 42009 } }
I20260812 06:19:36.346109 30764 catalog_manager.cc:5719] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed reported cstate change: term changed from 0 to 1, leader changed from <none> to ef853ddf72fa4cdb8ad577a97e0ad5ed (127.29.252.193). New cstate: current_term: 1 leader_uuid: "ef853ddf72fa4cdb8ad577a97e0ad5ed" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ef853ddf72fa4cdb8ad577a97e0ad5ed" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 42009 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:36.415321 30707 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.012s	sys 0.017s
I20260812 06:19:36.536449 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=15.086190
I20260812 06:19:36.695813 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.159s	user 0.120s	sys 0.036s Metrics: {"bytes_written":8779420,"cfile_init":1,"compiler_manager_pool.queue_time_us":239,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1039,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34890,"lbm_writes_lt_1ms":571,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":581376,"thread_start_us":129,"threads_started":1,"update_count":1070}
I20260812 06:19:36.697175 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): free 8725963 bytes of WAL
I20260812 06:19:36.697562 30871 log_reader.cc:385] T 6e9f36b213d342cf8dbfbadf05f7ccd7: removed 1 log segments from log reader
I20260812 06:19:36.697697 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000001 (ops 1-6)
I20260812 06:19:36.700045 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:36.700516 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): 12308958 bytes on disk
I20260812 06:19:36.701184 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.701728 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:36.726061 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.024s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3528309,"delete_count":0,"lbm_write_time_us":5413,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:36.726651 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:36.743552 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.744102 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:36.891242 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.147s	user 0.115s	sys 0.028s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631423,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":292,"lbm_read_time_us":10630,"lbm_reads_lt_1ms":465,"lbm_write_time_us":25838,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":279,"threads_started":5,"update_count":2000}
I20260812 06:19:36.891769 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:36.939009 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.047s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15261,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.939538 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:36.952126 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.952616 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:37.091272 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.138s	user 0.102s	sys 0.036s 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":453,"lbm_read_time_us":8756,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28245,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.092077 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:37.146359 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.054s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.146914 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:37.158114 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.158588 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:37.304060 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.145s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":11512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21112,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:37.304544 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:37.338136 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.033s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14531,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.338681 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:37.446396 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.108s	user 0.087s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":208,"lbm_read_time_us":6496,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20384,"lbm_writes_lt_1ms":343,"mutex_wait_us":18,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":1500}
I20260812 06:19:37.446849 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:37.488330 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.041s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15721,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.489372 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:37.499975 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3618,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.500543 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:37.631809 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.131s	user 0.103s	sys 0.028s 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":1060,"lbm_read_time_us":8562,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25918,"lbm_writes_lt_1ms":443,"mutex_wait_us":253,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.632287 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:37.675913 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.043s	user 0.020s	sys 0.018s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14065,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.676440 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:37.686785 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.687232 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:37.828261 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.141s	user 0.105s	sys 0.036s 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":288,"lbm_read_time_us":10653,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23007,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.828969 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:37.875178 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.046s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16687,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.875720 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:37.885980 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.886711 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:38.004709 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.118s	user 0.090s	sys 0.028s 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":241,"lbm_read_time_us":8498,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21597,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:19:38.005302 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:38.045192 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.040s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15401,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.045883 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:38.057168 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3892,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.057703 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:38.089140 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1281,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1476,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:38.090092 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): free 136728231 bytes of WAL
I20260812 06:19:38.090304 30871 log_reader.cc:385] T 6e9f36b213d342cf8dbfbadf05f7ccd7: removed 13 log segments from log reader
I20260812 06:19:38.090345 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000002 (ops 7-11)
I20260812 06:19:38.090381 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000003 (ops 12-16)
I20260812 06:19:38.090415 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000004 (ops 17-21)
I20260812 06:19:38.090448 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000005 (ops 22-26)
I20260812 06:19:38.090500 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000006 (ops 27-31)
I20260812 06:19:38.090536 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000007 (ops 32-36)
I20260812 06:19:38.090560 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000008 (ops 37-41)
I20260812 06:19:38.090590 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000009 (ops 42-46)
I20260812 06:19:38.090619 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000010 (ops 47-51)
I20260812 06:19:38.090651 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000011 (ops 52-56)
I20260812 06:19:38.090682 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000012 (ops 57-61)
I20260812 06:19:38.090713 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000013 (ops 62-66)
I20260812 06:19:38.090744 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000014 (ops 67-71)
I20260812 06:19:38.117343 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:38.117808 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=4.173312
I20260812 06:19:38.130843 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5456464,"delete_count":0,"lbm_write_time_us":5079,"lbm_writes_lt_1ms":136,"reinsert_count":0,"update_count":665}
I20260812 06:19:38.131309 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.196750
I20260812 06:19:38.141403 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":2782,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:38.141871 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): 482 bytes on disk
I20260812 06:19:38.142360 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.142897 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:38.323513 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.180s	user 0.108s	sys 0.062s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836344,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":9508,"lbm_read_time_us":10901,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36301,"lbm_writes_lt_1ms":643,"mutex_wait_us":2504,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:38.324079 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=14.095187
I20260812 06:19:38.390975 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.067s	user 0.035s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26291,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.391783 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=3.181125
I20260812 06:19:38.414088 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.022s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4471876,"delete_count":0,"lbm_write_time_us":5670,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:19:38.414562 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:38.426186 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:38.426838 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:38.597425 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.170s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836246,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":301,"lbm_read_time_us":11774,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34442,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":3000}
I20260812 06:19:38.598093 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=14.095187
I20260812 06:19:38.645076 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.047s	user 0.020s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17881,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.645699 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:38.664106 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6732,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.664624 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:38.831247 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.166s	user 0.125s	sys 0.034s 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":593,"lbm_read_time_us":10664,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32318,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":2500}
I20260812 06:19:38.832273 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=14.095187
I20260812 06:19:38.877187 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19050,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.877743 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:39.037520 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.160s	user 0.112s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":245,"lbm_read_time_us":9410,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27318,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:19:39.038062 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=11.118625
I20260812 06:19:39.091253 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.053s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":23382,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.091934 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:39.103892 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4431,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.104391 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:39.116461 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.116962 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:39.289703 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.173s	user 0.118s	sys 0.048s 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":387,"lbm_read_time_us":11890,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25855,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:19:39.290354 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=11.118625
I20260812 06:19:39.328703 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.038s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15817,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.329945 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:39.347908 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.018s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5421,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.348508 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:39.481246 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.133s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":359,"lbm_read_time_us":8014,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26676,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.481982 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=11.118625
I20260812 06:19:39.511202 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.029s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12365,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.511790 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:39.527534 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.528096 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:39.560833 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1537,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:39.561630 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): free 120553393 bytes of WAL
I20260812 06:19:39.562188 30871 log_reader.cc:385] T 6e9f36b213d342cf8dbfbadf05f7ccd7: removed 12 log segments from log reader
I20260812 06:19:39.562319 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000015 (ops 72-76)
I20260812 06:19:39.562429 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000016 (ops 77-81)
I20260812 06:19:39.562484 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000017 (ops 82-86)
I20260812 06:19:39.562528 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000018 (ops 87-91)
I20260812 06:19:39.562565 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000019 (ops 92-96)
I20260812 06:19:39.562604 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000020 (ops 97-100)
I20260812 06:19:39.562644 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000021 (ops 101-105)
I20260812 06:19:39.562676 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000022 (ops 106-110)
I20260812 06:19:39.562712 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000023 (ops 111-115)
I20260812 06:19:39.562749 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000024 (ops 116-120)
I20260812 06:19:39.562786 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000025 (ops 121-124)
I20260812 06:19:39.562824 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000026 (ops 125-129)
I20260812 06:19:39.587570 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:39.588091 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): 483 bytes on disk
I20260812 06:19:39.588505 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.588991 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=5.165500
I20260812 06:19:39.608247 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":7302547,"delete_count":0,"lbm_write_time_us":7586,"lbm_writes_lt_1ms":181,"reinsert_count":0,"update_count":890}
I20260812 06:19:39.610325 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:39.793473 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.183s	user 0.124s	sys 0.045s Metrics: {"cfile_cache_miss":611,"cfile_cache_miss_bytes":27933716,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1017,"lbm_read_time_us":14124,"lbm_reads_lt_1ms":647,"lbm_write_time_us":33271,"lbm_writes_lt_1ms":621,"mutex_wait_us":21,"peak_mem_usage":72558934,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":84,"threads_started":1,"update_count":2890}
I20260812 06:19:39.794093 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=15.087375
I20260812 06:19:39.838800 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.045s	user 0.020s	sys 0.023s Metrics: {"bytes_written":17312441,"delete_count":0,"lbm_write_time_us":19324,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2110}
I20260812 06:19:39.839362 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:39.850488 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.850943 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:40.007491 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.156s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":554,"cfile_cache_miss_bytes":25636263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":968,"lbm_read_time_us":10399,"lbm_reads_lt_1ms":594,"lbm_write_time_us":33707,"lbm_writes_lt_1ms":565,"peak_mem_usage":65059054,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2610}
I20260812 06:19:40.008035 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=14.095187
I20260812 06:19:40.054637 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.046s	user 0.030s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17241,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.055161 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:40.065608 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.066099 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:40.218605 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.152s	user 0.106s	sys 0.044s 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":1189,"lbm_read_time_us":10751,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29045,"lbm_writes_lt_1ms":543,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:40.219986 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=12.110812
I20260812 06:19:40.257956 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":14988,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:19:40.258610 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:40.277478 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.019s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3200109,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:19:40.277964 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:40.287067 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3178,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.287519 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:40.449774 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.162s	user 0.122s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733814,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1079,"lbm_read_time_us":12548,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25687,"lbm_writes_lt_1ms":543,"mutex_wait_us":249,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:19:40.450320 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=14.095187
I20260812 06:19:40.504179 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.054s	user 0.026s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21009,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.504696 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:40.515480 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.516152 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:40.674804 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.158s	user 0.102s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":13224,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24407,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.675614 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=14.095187
I20260812 06:19:40.730078 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.054s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17379,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.730628 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:40.741390 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.741870 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:40.904660 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.163s	user 0.094s	sys 0.065s 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":420,"lbm_read_time_us":12591,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26200,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:40.905220 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=11.118625
I20260812 06:19:40.939540 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.034s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14043,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:40.940084 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=2.188937
I20260812 06:19:40.962863 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.023s	user 0.008s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4273,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.963487 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:41.003507 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushMRSOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.040s	user 0.019s	sys 0.008s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1678,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:41.004172 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): free 133024609 bytes of WAL
I20260812 06:19:41.004383 30871 log_reader.cc:385] T 6e9f36b213d342cf8dbfbadf05f7ccd7: removed 13 log segments from log reader
I20260812 06:19:41.004653 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000027 (ops 130-134)
I20260812 06:19:41.004805 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000028 (ops 135-138)
I20260812 06:19:41.004952 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000029 (ops 139-143)
I20260812 06:19:41.005021 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000030 (ops 144-148)
I20260812 06:19:41.005039 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000031 (ops 149-153)
I20260812 06:19:41.005066 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000032 (ops 154-158)
I20260812 06:19:41.005098 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000033 (ops 159-163)
I20260812 06:19:41.005131 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000034 (ops 164-168)
I20260812 06:19:41.005163 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000035 (ops 169-173)
I20260812 06:19:41.005195 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000036 (ops 174-178)
I20260812 06:19:41.005228 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000037 (ops 179-183)
I20260812 06:19:41.005260 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000038 (ops 184-188)
I20260812 06:19:41.005292 30871 log.cc:1079] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/6e9f36b213d342cf8dbfbadf05f7ccd7/wal-000000039 (ops 189-193)
I20260812 06:19:41.032701 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: LogGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:41.033128 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7): 482 bytes on disk
I20260812 06:19:41.033560 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: UndoDeltaBlockGCOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.034212 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=6.157687
I20260812 06:19:41.059926 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.026s	user 0.017s	sys 0.003s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9173,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:41.060570 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=1.000000
I20260812 06:19:41.159193 30707 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.744s	user 1.747s	sys 0.094s
I20260812 06:19:41.242988 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: MajorDeltaCompactionOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.182s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836247,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":161,"lbm_read_time_us":12050,"lbm_reads_lt_1ms":661,"lbm_write_time_us":34057,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:19:41.243533 30973 maintenance_manager.cc:419] P ef853ddf72fa4cdb8ad577a97e0ad5ed: Scheduling FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7): perf score=10.126437
I20260812 06:19:41.249701 30707 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.001s	sys 0.002s
I20260812 06:19:41.250306 30707 tablet_server.cc:179] TabletServer@127.29.252.193:0 shutting down...
I20260812 06:19:41.281818 30871 maintenance_manager.cc:643] P ef853ddf72fa4cdb8ad577a97e0ad5ed: FlushDeltaMemStoresOp(6e9f36b213d342cf8dbfbadf05f7ccd7) complete. Timing: real 0.038s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11833,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.282528 30707 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:41.282898 30707 tablet_replica.cc:333] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed: stopping tablet replica
I20260812 06:19:41.283118 30707 raft_consensus.cc:2243] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.283325 30707 raft_consensus.cc:2272] T 6e9f36b213d342cf8dbfbadf05f7ccd7 P ef853ddf72fa4cdb8ad577a97e0ad5ed [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.298430 30707 tablet_server.cc:196] TabletServer@127.29.252.193:0 shutdown complete.
I20260812 06:19:41.303148 30707 master.cc:562] Master@127.29.252.254:46241 shutting down...
I20260812 06:19:41.307229 30707 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.307492 30707 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.307587 30707 tablet_replica.cc:333] T 00000000000000000000000000000000 P 777f750d83fd4ea890cb1ec3932935ca: stopping tablet replica
I20260812 06:19:41.319867 30707 master.cc:584] Master@127.29.252.254:46241 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5292 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:41.396378 30707 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.252.254:34199
I20260812 06:19:41.396741 30707 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.398947 31035 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.398969 31031 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:19:41.398945 31032 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.399291 30707 server_base.cc:1061] running on GCE node
I20260812 06:19:41.399442 30707 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.399478 30707 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:19:41.399497 30707 hybrid_clock.cc:648] HybridClock initialized: now 1786515581399497 us; error 0 us; skew 500 ppm
I20260812 06:19:41.400355 30707 webserver.cc:533] Webserver started at http://127.29.252.254:35465/ using document root <none> and password file <none>
I20260812 06:19:41.400516 30707 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.400568 30707 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.400641 30707 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.401017 30707 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/master-0-root/instance:
uuid: "0291e62d08f446af8e098fb1711d093b"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-t7g5"
I20260812 06:19:41.402738 30707 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:41.404122 31042 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:19:41.404363 30707 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:41.404441 30707 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/master-0-root
uuid: "0291e62d08f446af8e098fb1711d093b"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-t7g5"
I20260812 06:19:41.404520 30707 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-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:19:41.423812 30707 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.424228 30707 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.428221 30707 rpc_server.cc:307] RPC server started. Bound to: 127.29.252.254:34199
I20260812 06:19:41.436786 31134 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:19:41.436820 31133 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.252.254:34199 every 8 connection(s)
I20260812 06:19:41.438747 31134 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b: Bootstrap starting.
I20260812 06:19:41.439509 31134 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.440564 31134 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b: No bootstrap required, opened a new log
I20260812 06:19:41.440964 31134 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0291e62d08f446af8e098fb1711d093b" member_type: VOTER }
I20260812 06:19:41.441056 31134 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.441077 31134 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0291e62d08f446af8e098fb1711d093b, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.441282 31134 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [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: "0291e62d08f446af8e098fb1711d093b" member_type: VOTER }
I20260812 06:19:41.441375 31134 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.441416 31134 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.441474 31134 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.442219 31134 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0291e62d08f446af8e098fb1711d093b" member_type: VOTER }
I20260812 06:19:41.442353 31134 leader_election.cc:304] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [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: 0291e62d08f446af8e098fb1711d093b; no voters: 
I20260812 06:19:41.442559 31134 leader_election.cc:290] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.442757 31139 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.442939 31139 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 1 LEADER]: Becoming Leader. State: Replica: 0291e62d08f446af8e098fb1711d093b, State: Running, Role: LEADER
I20260812 06:19:41.443027 31134 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:41.443068 31139 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [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: "0291e62d08f446af8e098fb1711d093b" member_type: VOTER }
I20260812 06:19:41.443492 31144 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0291e62d08f446af8e098fb1711d093b. Latest consensus state: current_term: 1 leader_uuid: "0291e62d08f446af8e098fb1711d093b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0291e62d08f446af8e098fb1711d093b" member_type: VOTER } }
I20260812 06:19:41.443584 31144 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.443477 31141 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0291e62d08f446af8e098fb1711d093b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0291e62d08f446af8e098fb1711d093b" member_type: VOTER } }
I20260812 06:19:41.443636 31141 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.444118 31153 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:41.444823 31153 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:41.444999 30707 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:41.446645 31153 catalog_manager.cc:1383] Generated new cluster ID: 9372fdee64084c24891f74979b41754e
I20260812 06:19:41.446708 31153 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:41.462440 31153 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:41.463023 31153 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:41.473827 31153 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b: Generated new TSK 0
I20260812 06:19:41.474018 31153 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:41.477505 30707 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.479462 31179 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:19:41.479666 30707 server_base.cc:1061] running on GCE node
W20260812 06:19:41.479522 31173 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:19:41.479476 31177 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.479938 30707 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.479983 30707 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:19:41.479998 30707 hybrid_clock.cc:648] HybridClock initialized: now 1786515581479998 us; error 0 us; skew 500 ppm
I20260812 06:19:41.480929 30707 webserver.cc:533] Webserver started at http://127.29.252.193:43625/ using document root <none> and password file <none>
I20260812 06:19:41.481092 30707 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.481153 30707 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.481206 30707 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.481690 30707 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/instance:
uuid: "ae5e9fb98b214e09a48b64dd20c57a5e"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-t7g5"
I20260812 06:19:41.483268 30707 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:41.484349 31187 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:19:41.484709 30707 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:41.484802 30707 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root
uuid: "ae5e9fb98b214e09a48b64dd20c57a5e"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-t7g5"
I20260812 06:19:41.484874 30707 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-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:19:41.506619 30707 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.507035 30707 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.507345 30707 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:41.507820 30707 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:41.507859 30707 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.507915 30707 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:41.507944 30707 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.512217 30707 rpc_server.cc:307] RPC server started. Bound to: 127.29.252.193:36719
I20260812 06:19:41.512720 31286 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.252.193:36719 every 8 connection(s)
I20260812 06:19:41.521538 31292 heartbeater.cc:344] Connected to a master server at 127.29.252.254:34199
I20260812 06:19:41.521687 31292 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:41.521927 31292 heartbeater.cc:507] Master 127.29.252.254:34199 requested a full tablet report, sending...
I20260812 06:19:41.522794 31073 ts_manager.cc:194] Registered new tserver with Master: ae5e9fb98b214e09a48b64dd20c57a5e (127.29.252.193:36719)
I20260812 06:19:41.523082 30707 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010256078s
I20260812 06:19:41.523558 31073 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60058
I20260812 06:19:41.530844 31073 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60066:
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:19:41.540777 31234 tablet_service.cc:1511] Processing CreateTablet for tablet 57d4bf795ea54eb49a8e005b1f1e3526 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5d3c6d9bf7fa43598ee12072f7b778a0]), partition=
I20260812 06:19:41.541086 31234 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 57d4bf795ea54eb49a8e005b1f1e3526. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.543068 31315 tablet_bootstrap.cc:492] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Bootstrap starting.
I20260812 06:19:41.543962 31315 tablet_bootstrap.cc:654] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.545104 31315 tablet_bootstrap.cc:492] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: No bootstrap required, opened a new log
I20260812 06:19:41.545182 31315 ts_tablet_manager.cc:1403] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:41.545617 31315 raft_consensus.cc:359] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae5e9fb98b214e09a48b64dd20c57a5e" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 36719 } }
I20260812 06:19:41.545763 31315 raft_consensus.cc:385] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.545799 31315 raft_consensus.cc:740] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae5e9fb98b214e09a48b64dd20c57a5e, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.546133 31315 consensus_queue.cc:260] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [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: "ae5e9fb98b214e09a48b64dd20c57a5e" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 36719 } }
I20260812 06:19:41.546244 31315 raft_consensus.cc:399] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.546289 31315 raft_consensus.cc:493] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.546339 31315 raft_consensus.cc:3060] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.547063 31315 raft_consensus.cc:515] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae5e9fb98b214e09a48b64dd20c57a5e" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 36719 } }
I20260812 06:19:41.547199 31315 leader_election.cc:304] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [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: ae5e9fb98b214e09a48b64dd20c57a5e; no voters: 
I20260812 06:19:41.547402 31315 leader_election.cc:290] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.547559 31319 raft_consensus.cc:2804] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.547725 31315 ts_tablet_manager.cc:1434] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:41.547761 31292 heartbeater.cc:499] Master 127.29.252.254:34199 was elected leader, sending a full tablet report...
I20260812 06:19:41.547755 31319 raft_consensus.cc:697] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 1 LEADER]: Becoming Leader. State: Replica: ae5e9fb98b214e09a48b64dd20c57a5e, State: Running, Role: LEADER
I20260812 06:19:41.547984 31319 consensus_queue.cc:237] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [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: "ae5e9fb98b214e09a48b64dd20c57a5e" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 36719 } }
I20260812 06:19:41.549430 31073 catalog_manager.cc:5719] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e reported cstate change: term changed from 0 to 1, leader changed from <none> to ae5e9fb98b214e09a48b64dd20c57a5e (127.29.252.193). New cstate: current_term: 1 leader_uuid: "ae5e9fb98b214e09a48b64dd20c57a5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae5e9fb98b214e09a48b64dd20c57a5e" member_type: VOTER last_known_addr { host: "127.29.252.193" port: 36719 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:41.615101 30707 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.016s	sys 0.008s
I20260812 06:19:41.763322 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=19.054940
I20260812 06:19:41.928936 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.165s	user 0.113s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":716,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40176,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":15232,"update_count":1500}
I20260812 06:19:41.929842 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526): free 20743880 bytes of WAL
I20260812 06:19:41.930080 31198 log_reader.cc:385] T 57d4bf795ea54eb49a8e005b1f1e3526: removed 2 log segments from log reader
I20260812 06:19:41.930128 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000001 (ops 1-6)
I20260812 06:19:41.930162 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000002 (ops 7-11)
I20260812 06:19:41.934826 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:41.935369 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526): 16411398 bytes on disk
I20260812 06:19:41.936038 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.936702 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:41.950645 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.951261 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:42.125177 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.174s	user 0.113s	sys 0.048s 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":607,"lbm_read_time_us":11316,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25505,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":302,"threads_started":5,"update_count":2000}
I20260812 06:19:42.125836 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=14.095187
I20260812 06:19:42.166347 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.166908 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:42.315209 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.148s	user 0.107s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1199,"lbm_read_time_us":12200,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22672,"lbm_writes_lt_1ms":443,"mutex_wait_us":383,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:42.315727 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=11.118625
I20260812 06:19:42.343946 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.028s	user 0.025s	sys 0.001s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12008,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:42.344524 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:42.356520 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.357180 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:42.490562 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.133s	user 0.104s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":452,"lbm_read_time_us":9151,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24698,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:42.491142 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:42.533298 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.042s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15005,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.534174 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:42.551379 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.552073 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:42.686483 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.134s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":287,"lbm_read_time_us":9498,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26959,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35840,"update_count":2000}
I20260812 06:19:42.687325 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:42.731626 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.044s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16341,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.732270 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:42.743988 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.744462 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:42.877635 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.133s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":9818,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24074,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:19:42.878305 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:42.922515 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.044s	user 0.016s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14502,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.923439 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:42.934623 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.935141 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:43.093966 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.159s	user 0.115s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":11691,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24709,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2000}
I20260812 06:19:43.096511 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:43.139254 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.042s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19141,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.139767 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:43.151239 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.151697 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:43.182230 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.030s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":319,"dirs.run_wall_time_us":1301,"drs_written":1,"lbm_read_time_us":150,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1524,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:43.182906 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526): free 115943174 bytes of WAL
I20260812 06:19:43.183276 31198 log_reader.cc:385] T 57d4bf795ea54eb49a8e005b1f1e3526: removed 11 log segments from log reader
I20260812 06:19:43.183348 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000003 (ops 12-16)
I20260812 06:19:43.183391 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000004 (ops 17-21)
I20260812 06:19:43.183578 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000005 (ops 22-26)
I20260812 06:19:43.183643 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000006 (ops 27-31)
I20260812 06:19:43.183853 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000007 (ops 32-36)
I20260812 06:19:43.183897 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000008 (ops 37-41)
I20260812 06:19:43.183928 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000009 (ops 42-46)
I20260812 06:19:43.183959 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000010 (ops 47-51)
I20260812 06:19:43.183988 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000011 (ops 52-56)
I20260812 06:19:43.184018 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000012 (ops 57-61)
I20260812 06:19:43.184048 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000013 (ops 62-66)
I20260812 06:19:43.208029 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:43.208832 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526): 447 bytes on disk
I20260812 06:19:43.209470 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.210266 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=3.181125
I20260812 06:19:43.233105 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.023s	user 0.002s	sys 0.017s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.233731 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:43.243839 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.244376 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:43.459947 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.215s	user 0.123s	sys 0.086s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":718,"lbm_read_time_us":15296,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35614,"lbm_writes_lt_1ms":643,"mutex_wait_us":288,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:19:43.460526 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=14.095187
I20260812 06:19:43.522179 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.061s	user 0.012s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18352,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.522763 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:43.538552 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.539106 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:43.724177 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.185s	user 0.123s	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":173,"lbm_read_time_us":15208,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29802,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:43.724766 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=11.118625
I20260812 06:19:43.760062 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14758,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.760584 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:43.786552 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.026s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.787055 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:43.805763 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.018s	user 0.009s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.806430 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:43.979497 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.173s	user 0.113s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":288,"lbm_read_time_us":12335,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28949,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:43.980067 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=11.118625
I20260812 06:19:44.018433 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.038s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15401,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.019835 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:44.042841 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.023s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.043347 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:44.054287 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.054980 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:44.255318 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.200s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1158,"lbm_read_time_us":12443,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31185,"lbm_writes_lt_1ms":543,"mutex_wait_us":354,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:44.255919 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=14.095187
I20260812 06:19:44.300750 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.045s	user 0.032s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.301222 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:44.312989 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.313978 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:44.480846 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.167s	user 0.101s	sys 0.059s 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":700,"lbm_read_time_us":12843,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30150,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:44.481349 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=11.118625
I20260812 06:19:44.513689 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.032s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12793,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.514192 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:44.526973 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.527501 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:44.655810 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.128s	user 0.116s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":387,"lbm_read_time_us":7617,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22749,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:19:44.656543 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:44.701090 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.044s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15938,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.701926 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:44.714041 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.714838 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:44.747424 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":321,"dirs.run_wall_time_us":1383,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1667,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:44.748181 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526): free 120553382 bytes of WAL
I20260812 06:19:44.748415 31198 log_reader.cc:385] T 57d4bf795ea54eb49a8e005b1f1e3526: removed 12 log segments from log reader
I20260812 06:19:44.748476 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000014 (ops 67-71)
I20260812 06:19:44.748512 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000015 (ops 72-76)
I20260812 06:19:44.748534 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000016 (ops 77-81)
I20260812 06:19:44.748555 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000017 (ops 82-86)
I20260812 06:19:44.748581 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000018 (ops 87-91)
I20260812 06:19:44.748605 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000019 (ops 92-96)
I20260812 06:19:44.748628 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000020 (ops 97-101)
I20260812 06:19:44.748664 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000021 (ops 102-106)
I20260812 06:19:44.748696 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000022 (ops 107-110)
I20260812 06:19:44.748734 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000023 (ops 111-115)
I20260812 06:19:44.748772 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000024 (ops 116-120)
I20260812 06:19:44.748805 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000025 (ops 121-124)
I20260812 06:19:44.776721 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:44.777207 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=3.181125
I20260812 06:19:44.792164 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.015s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:44.792670 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526): 472 bytes on disk
I20260812 06:19:44.793143 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526) 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:19:44.793740 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:44.806116 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.806924 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:44.992892 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.186s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1312,"lbm_read_time_us":13978,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36951,"lbm_writes_lt_1ms":643,"mutex_wait_us":706,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":113,"threads_started":1,"update_count":3000}
I20260812 06:19:44.993721 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=14.095187
I20260812 06:19:45.046175 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.052s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23240,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.046749 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:45.059819 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.060338 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:45.210376 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.149s	user 0.122s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":10268,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29075,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:19:45.211014 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:45.241120 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.030s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12536,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.241875 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:45.257812 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.258386 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:45.407035 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.148s	user 0.100s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":424,"lbm_read_time_us":9505,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25034,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:45.408064 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:45.439954 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13281,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.441789 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:45.454306 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.454825 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:45.600342 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.145s	user 0.098s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":836,"lbm_read_time_us":7837,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24598,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:45.601018 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:45.643172 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.042s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15703,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.643738 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:45.657182 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.658138 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:45.782068 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.124s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1135,"lbm_read_time_us":8413,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22041,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:45.782635 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:45.822862 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.040s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16733,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.823680 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:45.835261 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.836261 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:45.968480 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.132s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1136,"lbm_read_time_us":8769,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26080,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:19:45.969159 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:46.020944 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.052s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15211,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.021634 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:46.038796 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.039466 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:46.186830 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.147s	user 0.098s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":11423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24542,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:19:46.187433 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=10.126437
I20260812 06:19:46.237203 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.050s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.237879 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:46.253955 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.254595 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:46.284765 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushMRSOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":114,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1454,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1807,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:46.285548 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526): free 129320758 bytes of WAL
I20260812 06:19:46.285812 31198 log_reader.cc:385] T 57d4bf795ea54eb49a8e005b1f1e3526: removed 13 log segments from log reader
I20260812 06:19:46.285876 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000026 (ops 125-129)
I20260812 06:19:46.285914 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000027 (ops 130-134)
I20260812 06:19:46.285938 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000028 (ops 135-139)
I20260812 06:19:46.285961 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000029 (ops 140-144)
I20260812 06:19:46.285985 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000030 (ops 145-148)
I20260812 06:19:46.286023 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000031 (ops 149-153)
I20260812 06:19:46.286047 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000032 (ops 154-158)
I20260812 06:19:46.286067 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000033 (ops 159-162)
I20260812 06:19:46.286088 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000034 (ops 163-167)
I20260812 06:19:46.286110 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000035 (ops 168-172)
I20260812 06:19:46.286130 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000036 (ops 173-177)
I20260812 06:19:46.286167 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000037 (ops 178-182)
I20260812 06:19:46.286192 31198 log.cc:1079] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: Deleting log segment in path: /tmp/dist-test-taskrtZato/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576092085-30707-0/minicluster-data/ts-0-root/wals/57d4bf795ea54eb49a8e005b1f1e3526/wal-000000038 (ops 183-187)
I20260812 06:19:46.314684 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: LogGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.029s	user 0.003s	sys 0.025s Metrics: {}
I20260812 06:19:46.315212 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:46.340631 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.025s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:19:46.341394 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526): 481 bytes on disk
I20260812 06:19:46.341972 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: UndoDeltaBlockGCOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.342564 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:46.358443 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6020,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:46.359030 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:46.573918 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.215s	user 0.154s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":613,"lbm_read_time_us":15174,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35870,"lbm_writes_lt_1ms":643,"mutex_wait_us":830,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:46.574463 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=14.095187
I20260812 06:19:46.616411 30707 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.001s	user 1.817s	sys 0.149s
I20260812 06:19:46.624130 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.050s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23962,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.624584 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=2.188937
I20260812 06:19:46.634613 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: FlushDeltaMemStoresOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.635061 31294 maintenance_manager.cc:419] P ae5e9fb98b214e09a48b64dd20c57a5e: Scheduling MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526): perf score=1.000000
I20260812 06:19:46.663749 30707 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.047s	user 0.001s	sys 0.000s
I20260812 06:19:46.664269 30707 tablet_server.cc:179] TabletServer@127.29.252.193:0 shutting down...
I20260812 06:19:46.794672 31198 maintenance_manager.cc:643] P ae5e9fb98b214e09a48b64dd20c57a5e: MajorDeltaCompactionOp(57d4bf795ea54eb49a8e005b1f1e3526) complete. Timing: real 0.159s	user 0.093s	sys 0.061s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512298,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":819,"lbm_read_time_us":8227,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24846,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:19:46.795223 30707 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:46.795421 30707 tablet_replica.cc:333] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e: stopping tablet replica
I20260812 06:19:46.795593 30707 raft_consensus.cc:2243] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:46.795749 30707 raft_consensus.cc:2272] T 57d4bf795ea54eb49a8e005b1f1e3526 P ae5e9fb98b214e09a48b64dd20c57a5e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:46.799880 30707 tablet_server.cc:196] TabletServer@127.29.252.193:0 shutdown complete.
I20260812 06:19:46.839965 30707 master.cc:562] Master@127.29.252.254:34199 shutting down...
I20260812 06:19:46.843580 30707 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:46.843855 30707 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:46.843916 30707 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0291e62d08f446af8e098fb1711d093b: stopping tablet replica
I20260812 06:19:46.856933 30707 master.cc:584] Master@127.29.252.254:34199 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5541 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10835 ms total)

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