[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:04.861667 15763 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.100.254:39211
I20260812 06:17:04.862588 15763 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:04.863154 15763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.869273 15774 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.869398 15771 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.869438 15763 server_base.cc:1061] running on GCE node
W20260812 06:17:04.869547 15770 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.869966 15763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.870067 15763 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:04.870122 15763 hybrid_clock.cc:648] HybridClock initialized: now 1786515424870120 us; error 0 us; skew 500 ppm
I20260812 06:17:04.871858 15763 webserver.cc:533] Webserver started at http://127.15.100.254:43247/ using document root <none> and password file <none>
I20260812 06:17:04.872385 15763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.872452 15763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.872681 15763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.874275 15763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/master-0-root/instance:
uuid: "9283fcce66fe48d69ac9b9ea2f740bb0"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-1l3l"
I20260812 06:17:04.877636 15763 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:04.879819 15782 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.880789 15763 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:04.880894 15763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/master-0-root
uuid: "9283fcce66fe48d69ac9b9ea2f740bb0"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-1l3l"
I20260812 06:17:04.880977 15763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:04.892519 15763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.893082 15763 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:04.893227 15763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.900290 15763 rpc_server.cc:307] RPC server started. Bound to: 127.15.100.254:39211
I20260812 06:17:04.900318 15881 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.100.254:39211 every 8 connection(s)
I20260812 06:17:04.902484 15882 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:04.907692 15882 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: Bootstrap starting.
I20260812 06:17:04.909924 15882 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.910743 15882 log.cc:826] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:04.912354 15882 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: No bootstrap required, opened a new log
I20260812 06:17:04.915051 15882 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9283fcce66fe48d69ac9b9ea2f740bb0" member_type: VOTER }
I20260812 06:17:04.915215 15882 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.915262 15882 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9283fcce66fe48d69ac9b9ea2f740bb0, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.915872 15882 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [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: "9283fcce66fe48d69ac9b9ea2f740bb0" member_type: VOTER }
I20260812 06:17:04.916016 15882 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.916064 15882 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.916146 15882 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:04.916842 15882 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9283fcce66fe48d69ac9b9ea2f740bb0" member_type: VOTER }
I20260812 06:17:04.917219 15882 leader_election.cc:304] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [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: 9283fcce66fe48d69ac9b9ea2f740bb0; no voters: 
I20260812 06:17:04.917480 15882 leader_election.cc:290] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:04.917598 15887 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:04.917815 15887 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 1 LEADER]: Becoming Leader. State: Replica: 9283fcce66fe48d69ac9b9ea2f740bb0, State: Running, Role: LEADER
I20260812 06:17:04.918202 15887 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [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: "9283fcce66fe48d69ac9b9ea2f740bb0" member_type: VOTER }
I20260812 06:17:04.918373 15882 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:04.920156 15888 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9283fcce66fe48d69ac9b9ea2f740bb0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9283fcce66fe48d69ac9b9ea2f740bb0" member_type: VOTER } }
I20260812 06:17:04.920181 15889 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9283fcce66fe48d69ac9b9ea2f740bb0. Latest consensus state: current_term: 1 leader_uuid: "9283fcce66fe48d69ac9b9ea2f740bb0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9283fcce66fe48d69ac9b9ea2f740bb0" member_type: VOTER } }
I20260812 06:17:04.920290 15888 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.920291 15889 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.920555 15763 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:04.922618 15905 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:04.922680 15905 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:04.922748 15903 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:04.923425 15903 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:04.928288 15903 catalog_manager.cc:1383] Generated new cluster ID: fb19aa8b915941b782a3da4c1d5d8c89
I20260812 06:17:04.928339 15903 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:04.939512 15903 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:04.940645 15903 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:04.951381 15903 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: Generated new TSK 0
I20260812 06:17:04.952178 15903 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:04.985426 15763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.988210 15912 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.988267 15763 server_base.cc:1061] running on GCE node
W20260812 06:17:04.988211 15910 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.988430 15915 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.988659 15763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.988704 15763 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:04.988725 15763 hybrid_clock.cc:648] HybridClock initialized: now 1786515424988725 us; error 0 us; skew 500 ppm
I20260812 06:17:04.989619 15763 webserver.cc:533] Webserver started at http://127.15.100.193:44677/ using document root <none> and password file <none>
I20260812 06:17:04.989771 15763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.989832 15763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.989912 15763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.990283 15763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/instance:
uuid: "54163ff784bd41ca959727ace8cd7442"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-1l3l"
I20260812 06:17:04.991758 15763 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:04.992682 15920 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.992935 15763 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.993003 15763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root
uuid: "54163ff784bd41ca959727ace8cd7442"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-1l3l"
I20260812 06:17:04.993075 15763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:05.004459 15763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:05.004912 15763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:05.005398 15763 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:05.006258 15763 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:05.006313 15763 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:05.006372 15763 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:05.006398 15763 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:05.013163 15763 rpc_server.cc:307] RPC server started. Bound to: 127.15.100.193:34267
I20260812 06:17:05.013213 16038 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.100.193:34267 every 8 connection(s)
I20260812 06:17:05.029760 16039 heartbeater.cc:344] Connected to a master server at 127.15.100.254:39211
I20260812 06:17:05.030026 16039 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:05.030476 16039 heartbeater.cc:507] Master 127.15.100.254:39211 requested a full tablet report, sending...
I20260812 06:17:05.031860 15815 ts_manager.cc:194] Registered new tserver with Master: 54163ff784bd41ca959727ace8cd7442 (127.15.100.193:34267)
I20260812 06:17:05.031983 15763 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018170459s
I20260812 06:17:05.033067 15815 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44018
I20260812 06:17:05.041448 15815 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44022:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:05.055774 15983 tablet_service.cc:1511] Processing CreateTablet for tablet fc952d869ba24c15b73fcb1a05275b13 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b64bac1b58f04ff8ae08435a127067d2]), partition=
I20260812 06:17:05.056216 15983 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fc952d869ba24c15b73fcb1a05275b13. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:05.058435 16056 tablet_bootstrap.cc:492] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Bootstrap starting.
I20260812 06:17:05.059365 16056 tablet_bootstrap.cc:654] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:05.060814 16056 tablet_bootstrap.cc:492] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: No bootstrap required, opened a new log
I20260812 06:17:05.060899 16056 ts_tablet_manager.cc:1403] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:05.061322 16056 raft_consensus.cc:359] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "54163ff784bd41ca959727ace8cd7442" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 34267 } }
I20260812 06:17:05.061417 16056 raft_consensus.cc:385] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:05.061441 16056 raft_consensus.cc:740] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 54163ff784bd41ca959727ace8cd7442, State: Initialized, Role: FOLLOWER
I20260812 06:17:05.061555 16056 consensus_queue.cc:260] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [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: "54163ff784bd41ca959727ace8cd7442" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 34267 } }
I20260812 06:17:05.061625 16056 raft_consensus.cc:399] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:05.061650 16056 raft_consensus.cc:493] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:05.061697 16056 raft_consensus.cc:3060] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:05.062403 16056 raft_consensus.cc:515] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "54163ff784bd41ca959727ace8cd7442" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 34267 } }
I20260812 06:17:05.062520 16056 leader_election.cc:304] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [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: 54163ff784bd41ca959727ace8cd7442; no voters: 
I20260812 06:17:05.062703 16056 leader_election.cc:290] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:05.062814 16058 raft_consensus.cc:2804] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:05.062986 16058 raft_consensus.cc:697] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 1 LEADER]: Becoming Leader. State: Replica: 54163ff784bd41ca959727ace8cd7442, State: Running, Role: LEADER
I20260812 06:17:05.063040 16056 ts_tablet_manager.cc:1434] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:05.063346 16039 heartbeater.cc:499] Master 127.15.100.254:39211 was elected leader, sending a full tablet report...
I20260812 06:17:05.063722 16058 consensus_queue.cc:237] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [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: "54163ff784bd41ca959727ace8cd7442" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 34267 } }
I20260812 06:17:05.066532 15815 catalog_manager.cc:5719] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 reported cstate change: term changed from 0 to 1, leader changed from <none> to 54163ff784bd41ca959727ace8cd7442 (127.15.100.193). New cstate: current_term: 1 leader_uuid: "54163ff784bd41ca959727ace8cd7442" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "54163ff784bd41ca959727ace8cd7442" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 34267 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:05.126149 15763 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.010s	sys 0.013s
I20260812 06:17:05.264253 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13): perf score=19.054940
I20260812 06:17:05.454449 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.190s	user 0.119s	sys 0.068s Metrics: {"bytes_written":16409903,"cfile_init":1,"compiler_manager_pool.queue_time_us":185,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":925,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46450,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":98,"threads_started":1,"update_count":2000}
I20260812 06:17:05.455592 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling LogGCOp(fc952d869ba24c15b73fcb1a05275b13): free 20743880 bytes of WAL
I20260812 06:17:05.455958 15930 log_reader.cc:385] T fc952d869ba24c15b73fcb1a05275b13: removed 2 log segments from log reader
I20260812 06:17:05.456044 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000001 (ops 1-6)
I20260812 06:17:05.456102 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000002 (ops 7-11)
I20260812 06:17:05.460209 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: LogGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:05.460525 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13): 16411394 bytes on disk
I20260812 06:17:05.461012 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.461376 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=3.181125
I20260812 06:17:05.483017 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.022s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:05.483418 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:05.496280 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4838,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.496716 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:05.687034 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.190s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":511,"lbm_read_time_us":12737,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31768,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":277,"threads_started":5,"update_count":3000}
I20260812 06:17:05.687513 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:05.741024 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.053s	user 0.036s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.741560 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:05.751286 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.751736 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:05.925537 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.174s	user 0.108s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1057,"lbm_read_time_us":12695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27395,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:05.926050 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:05.982349 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.056s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18146,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:05.982909 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:05.997506 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.997964 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:06.170487 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.172s	user 0.112s	sys 0.048s 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":671,"lbm_read_time_us":12052,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27318,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:06.170979 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:06.232750 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.062s	user 0.023s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21559,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.233361 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:06.248126 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.248616 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:06.408816 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.160s	user 0.106s	sys 0.054s 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":933,"lbm_read_time_us":11409,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27793,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:06.409348 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=10.126437
I20260812 06:17:06.440928 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13469,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.441403 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:06.455265 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.455833 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:06.580240 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.124s	user 0.082s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":743,"lbm_read_time_us":6895,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24212,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:06.580971 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=10.126437
I20260812 06:17:06.612874 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.032s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.613332 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:06.624462 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.625073 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:06.652293 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1395,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1542,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:06.653028 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling LogGCOp(fc952d869ba24c15b73fcb1a05275b13): free 112239252 bytes of WAL
I20260812 06:17:06.653250 15930 log_reader.cc:385] T fc952d869ba24c15b73fcb1a05275b13: removed 11 log segments from log reader
I20260812 06:17:06.653296 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000003 (ops 12-16)
I20260812 06:17:06.653326 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000004 (ops 17-21)
I20260812 06:17:06.653357 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000005 (ops 22-26)
I20260812 06:17:06.653389 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000006 (ops 27-31)
I20260812 06:17:06.653422 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000007 (ops 32-36)
I20260812 06:17:06.653455 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000008 (ops 37-41)
I20260812 06:17:06.653487 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000009 (ops 42-46)
I20260812 06:17:06.653519 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000010 (ops 47-51)
I20260812 06:17:06.653550 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000011 (ops 52-56)
I20260812 06:17:06.653582 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000012 (ops 57-60)
I20260812 06:17:06.653614 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000013 (ops 61-65)
I20260812 06:17:06.674381 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: LogGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:06.674737 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13): 463 bytes on disk
I20260812 06:17:06.675140 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.675647 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=3.181125
I20260812 06:17:06.687947 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:06.688378 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:06.701611 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:06.702085 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:06.860702 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.158s	user 0.118s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":651,"lbm_read_time_us":12684,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30650,"lbm_writes_lt_1ms":643,"mutex_wait_us":286,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:06.861320 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:06.908037 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.047s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18954,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.908548 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:06.919404 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.920032 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:07.072526 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.152s	user 0.109s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1373,"lbm_read_time_us":11267,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27237,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:07.072988 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=11.118625
I20260812 06:17:07.111619 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.038s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14807,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.112597 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.123873 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.124331 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.133181 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3253,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.133670 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:07.269632 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.136s	user 0.112s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1456,"lbm_read_time_us":10495,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25862,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:07.270376 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=11.118625
I20260812 06:17:07.301834 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.031s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12944,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.302439 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.324213 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.022s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4839,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.324740 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.340173 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.340615 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:07.496353 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.156s	user 0.113s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1472,"lbm_read_time_us":11588,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29584,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:07.496847 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=11.118625
I20260812 06:17:07.532070 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.035s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14778,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.532589 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.556106 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.556602 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.571521 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.572093 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:07.722870 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.151s	user 0.117s	sys 0.031s 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":192,"lbm_read_time_us":9845,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28949,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2500}
I20260812 06:17:07.723552 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=12.110812
I20260812 06:17:07.762491 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.039s	user 0.016s	sys 0.020s Metrics: {"bytes_written":13620267,"delete_count":0,"lbm_write_time_us":16806,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:17:07.762992 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.196750
I20260812 06:17:07.773837 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3775,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:07.774334 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:07.924625 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.150s	user 0.118s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672250,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1082,"lbm_read_time_us":10315,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22248,"lbm_writes_lt_1ms":443,"mutex_wait_us":320,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:07.925143 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:07.976807 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.052s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:07.977363 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:07.994149 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3698,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.994637 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:08.032518 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.038s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1280,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2061,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:08.033300 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling LogGCOp(fc952d869ba24c15b73fcb1a05275b13): free 133024426 bytes of WAL
I20260812 06:17:08.033514 15930 log_reader.cc:385] T fc952d869ba24c15b73fcb1a05275b13: removed 13 log segments from log reader
I20260812 06:17:08.033560 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000014 (ops 66-70)
I20260812 06:17:08.033587 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000015 (ops 71-74)
I20260812 06:17:08.033618 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000016 (ops 75-79)
I20260812 06:17:08.033649 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000017 (ops 80-84)
I20260812 06:17:08.033684 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000018 (ops 85-89)
I20260812 06:17:08.033716 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000019 (ops 90-94)
I20260812 06:17:08.033749 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000020 (ops 95-99)
I20260812 06:17:08.033792 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000021 (ops 100-104)
I20260812 06:17:08.033824 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000022 (ops 105-109)
I20260812 06:17:08.033859 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000023 (ops 110-114)
I20260812 06:17:08.033891 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000024 (ops 115-119)
I20260812 06:17:08.033924 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000025 (ops 120-124)
I20260812 06:17:08.033957 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000026 (ops 125-129)
I20260812 06:17:08.057686 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: LogGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:08.058145 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13): 482 bytes on disk
I20260812 06:17:08.058668 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:08.059232 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=3.181125
I20260812 06:17:08.078776 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.019s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:08.079175 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:08.088272 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3256,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:08.088728 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:08.332050 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.243s	user 0.175s	sys 0.058s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":512,"lbm_read_time_us":15770,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37819,"lbm_writes_lt_1ms":743,"mutex_wait_us":54,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:17:08.332665 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=18.063937
I20260812 06:17:08.394356 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.061s	user 0.028s	sys 0.021s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":23095,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:08.394850 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:08.404991 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.405692 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:08.599814 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.194s	user 0.126s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":547,"lbm_read_time_us":12957,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31639,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:08.600344 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:08.641558 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16680,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.642110 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:08.656602 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.657125 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:08.840133 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.183s	user 0.120s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":11027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28530,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:08.840780 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:08.898546 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.058s	user 0.021s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21728,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.899060 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:08.909247 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.909678 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:09.087596 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.178s	user 0.115s	sys 0.051s 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":341,"lbm_read_time_us":13116,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":27985,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:17:09.088083 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:09.146762 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.059s	user 0.020s	sys 0.034s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23104,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.147349 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:09.157325 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.157852 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:09.322003 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.164s	user 0.099s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1631,"lbm_read_time_us":12298,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26800,"lbm_writes_lt_1ms":543,"mutex_wait_us":666,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:09.322561 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=11.118625
I20260812 06:17:09.354630 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.031s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13234,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:09.355223 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:09.372599 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6233,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.373121 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:09.403174 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushMRSOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1196,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1418,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:09.403883 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling LogGCOp(fc952d869ba24c15b73fcb1a05275b13): free 108082576 bytes of WAL
I20260812 06:17:09.404088 15930 log_reader.cc:385] T fc952d869ba24c15b73fcb1a05275b13: removed 11 log segments from log reader
I20260812 06:17:09.404134 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000027 (ops 130-134)
I20260812 06:17:09.404160 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000028 (ops 135-138)
I20260812 06:17:09.404187 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000029 (ops 139-143)
I20260812 06:17:09.404219 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000030 (ops 144-148)
I20260812 06:17:09.404248 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000031 (ops 149-153)
I20260812 06:17:09.404280 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000032 (ops 154-158)
I20260812 06:17:09.404311 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000033 (ops 159-162)
I20260812 06:17:09.404342 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000034 (ops 163-167)
I20260812 06:17:09.404371 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000035 (ops 168-172)
I20260812 06:17:09.404400 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000036 (ops 173-176)
I20260812 06:17:09.404433 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000037 (ops 177-181)
I20260812 06:17:09.424376 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: LogGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:09.424850 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13): 447 bytes on disk
I20260812 06:17:09.425283 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: UndoDeltaBlockGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.425940 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=3.181125
I20260812 06:17:09.443588 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.017s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:09.444063 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling LogGCOp(fc952d869ba24c15b73fcb1a05275b13): free 8767197 bytes of WAL
I20260812 06:17:09.444263 15930 log_reader.cc:385] T fc952d869ba24c15b73fcb1a05275b13: removed 1 log segments from log reader
I20260812 06:17:09.444320 15930 log.cc:1079] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/fc952d869ba24c15b73fcb1a05275b13/wal-000000038 (ops 182-186)
I20260812 06:17:09.446321 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: LogGCOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:09.446642 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:09.460644 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.461500 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:09.642568 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.181s	user 0.120s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":184,"lbm_read_time_us":13773,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30243,"lbm_writes_lt_1ms":643,"mutex_wait_us":76,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:09.643149 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=14.095187
I20260812 06:17:09.685791 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.042s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.686312 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13): perf score=2.188937
I20260812 06:17:09.696643 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: FlushDeltaMemStoresOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.697093 16041 maintenance_manager.cc:419] P 54163ff784bd41ca959727ace8cd7442: Scheduling MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13): perf score=1.000000
I20260812 06:17:09.774792 15763 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.649s	user 1.672s	sys 0.176s
I20260812 06:17:09.837312 15763 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.061s	user 0.002s	sys 0.000s
I20260812 06:17:09.837965 15763 tablet_server.cc:179] TabletServer@127.15.100.193:0 shutting down...
I20260812 06:17:09.845912 15930 maintenance_manager.cc:643] P 54163ff784bd41ca959727ace8cd7442: MajorDeltaCompactionOp(fc952d869ba24c15b73fcb1a05275b13) complete. Timing: real 0.149s	user 0.089s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":12097,"lbm_reads_lt_1ms":568,"lbm_write_time_us":24581,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":41472,"update_count":2500}
I20260812 06:17:09.846626 15763 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:09.847050 15763 tablet_replica.cc:333] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442: stopping tablet replica
I20260812 06:17:09.847285 15763 raft_consensus.cc:2243] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:09.847556 15763 raft_consensus.cc:2272] T fc952d869ba24c15b73fcb1a05275b13 P 54163ff784bd41ca959727ace8cd7442 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:09.865691 15763 tablet_server.cc:196] TabletServer@127.15.100.193:0 shutdown complete.
I20260812 06:17:09.891445 15763 master.cc:562] Master@127.15.100.254:39211 shutting down...
I20260812 06:17:09.894749 15763 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:09.894932 15763 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:09.895033 15763 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9283fcce66fe48d69ac9b9ea2f740bb0: stopping tablet replica
I20260812 06:17:09.907371 15763 master.cc:584] Master@127.15.100.254:39211 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5124 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:09.996842 15763 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.100.254:35945
I20260812 06:17:09.997255 15763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.999279 16087 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:09.999382 16086 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:09.999382 15763 server_base.cc:1061] running on GCE node
W20260812 06:17:09.999401 16090 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:09.999732 15763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.999783 15763 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:09.999814 15763 hybrid_clock.cc:648] HybridClock initialized: now 1786515429999813 us; error 0 us; skew 500 ppm
I20260812 06:17:10.000653 15763 webserver.cc:533] Webserver started at http://127.15.100.254:36143/ using document root <none> and password file <none>
I20260812 06:17:10.000820 15763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.000876 15763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.000955 15763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.001364 15763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/master-0-root/instance:
uuid: "e71d10ae12ab4da6b220f94e3d35b0e9"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-1l3l"
I20260812 06:17:10.002913 15763 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:10.003867 16100 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.004099 15763 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:10.004168 15763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/master-0-root
uuid: "e71d10ae12ab4da6b220f94e3d35b0e9"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-1l3l"
I20260812 06:17:10.004222 15763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:10.013444 15763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.013867 15763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.018347 15763 rpc_server.cc:307] RPC server started. Bound to: 127.15.100.254:35945
I20260812 06:17:10.020114 16201 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.023211 16197 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.100.254:35945 every 8 connection(s)
I20260812 06:17:10.023696 16201 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9: Bootstrap starting.
I20260812 06:17:10.024646 16201 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.025701 16201 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9: No bootstrap required, opened a new log
I20260812 06:17:10.026086 16201 raft_consensus.cc:359] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e71d10ae12ab4da6b220f94e3d35b0e9" member_type: VOTER }
I20260812 06:17:10.026178 16201 raft_consensus.cc:385] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.026201 16201 raft_consensus.cc:740] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e71d10ae12ab4da6b220f94e3d35b0e9, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.026325 16201 consensus_queue.cc:260] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [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: "e71d10ae12ab4da6b220f94e3d35b0e9" member_type: VOTER }
I20260812 06:17:10.026384 16201 raft_consensus.cc:399] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.026412 16201 raft_consensus.cc:493] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.026446 16201 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.027088 16201 raft_consensus.cc:515] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e71d10ae12ab4da6b220f94e3d35b0e9" member_type: VOTER }
I20260812 06:17:10.027215 16201 leader_election.cc:304] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [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: e71d10ae12ab4da6b220f94e3d35b0e9; no voters: 
I20260812 06:17:10.027402 16201 leader_election.cc:290] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.027575 16207 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.027817 16207 raft_consensus.cc:697] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 1 LEADER]: Becoming Leader. State: Replica: e71d10ae12ab4da6b220f94e3d35b0e9, State: Running, Role: LEADER
I20260812 06:17:10.027863 16201 sys_catalog.cc:565] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:10.027961 16207 consensus_queue.cc:237] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [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: "e71d10ae12ab4da6b220f94e3d35b0e9" member_type: VOTER }
I20260812 06:17:10.028400 16208 sys_catalog.cc:455] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e71d10ae12ab4da6b220f94e3d35b0e9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e71d10ae12ab4da6b220f94e3d35b0e9" member_type: VOTER } }
I20260812 06:17:10.028424 16209 sys_catalog.cc:455] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e71d10ae12ab4da6b220f94e3d35b0e9. Latest consensus state: current_term: 1 leader_uuid: "e71d10ae12ab4da6b220f94e3d35b0e9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e71d10ae12ab4da6b220f94e3d35b0e9" member_type: VOTER } }
I20260812 06:17:10.028501 16208 sys_catalog.cc:458] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.028527 16209 sys_catalog.cc:458] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.028748 16215 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:10.029672 16215 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:10.029848 15763 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:10.031549 16215 catalog_manager.cc:1383] Generated new cluster ID: 892f5a80106d41d2bba825646016ef18
I20260812 06:17:10.031599 16215 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:10.038760 16215 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:10.039304 16215 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:10.048857 16215 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9: Generated new TSK 0
I20260812 06:17:10.049074 16215 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:10.062521 15763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:10.064606 16232 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.064693 16237 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.064726 15763 server_base.cc:1061] running on GCE node
W20260812 06:17:10.064800 16234 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.065009 15763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.065054 15763 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:10.065069 15763 hybrid_clock.cc:648] HybridClock initialized: now 1786515430065069 us; error 0 us; skew 500 ppm
I20260812 06:17:10.066045 15763 webserver.cc:533] Webserver started at http://127.15.100.193:39965/ using document root <none> and password file <none>
I20260812 06:17:10.066205 15763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.066247 15763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.066305 15763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.066672 15763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/instance:
uuid: "a8820627e52d47da84503c93e3a1b0e7"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-1l3l"
I20260812 06:17:10.068321 15763 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:10.069372 16243 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.069739 15763 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:10.069808 15763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root
uuid: "a8820627e52d47da84503c93e3a1b0e7"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-1l3l"
I20260812 06:17:10.069872 15763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:10.092759 15763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.093160 15763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.093457 15763 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:10.093937 15763 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:10.093986 15763 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.094023 15763 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:10.094050 15763 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.098430 15763 rpc_server.cc:307] RPC server started. Bound to: 127.15.100.193:38863
I20260812 06:17:10.098474 16358 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.100.193:38863 every 8 connection(s)
I20260812 06:17:10.106128 16360 heartbeater.cc:344] Connected to a master server at 127.15.100.254:35945
I20260812 06:17:10.106266 16360 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:10.106549 16360 heartbeater.cc:507] Master 127.15.100.254:35945 requested a full tablet report, sending...
I20260812 06:17:10.107223 16127 ts_manager.cc:194] Registered new tserver with Master: a8820627e52d47da84503c93e3a1b0e7 (127.15.100.193:38863)
I20260812 06:17:10.107695 15763 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008888696s
I20260812 06:17:10.108172 16127 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41492
I20260812 06:17:10.115252 16127 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41496:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:10.123988 16284 tablet_service.cc:1511] Processing CreateTablet for tablet db41e41b1cc44a34a5b693210a8828d0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f93c2b9ff384476d94738eab1b306652]), partition=
I20260812 06:17:10.124279 16284 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet db41e41b1cc44a34a5b693210a8828d0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.126403 16393 tablet_bootstrap.cc:492] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Bootstrap starting.
I20260812 06:17:10.127317 16393 tablet_bootstrap.cc:654] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.128670 16393 tablet_bootstrap.cc:492] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: No bootstrap required, opened a new log
I20260812 06:17:10.128755 16393 ts_tablet_manager.cc:1403] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:10.129221 16393 raft_consensus.cc:359] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8820627e52d47da84503c93e3a1b0e7" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 38863 } }
I20260812 06:17:10.129333 16393 raft_consensus.cc:385] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.129362 16393 raft_consensus.cc:740] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a8820627e52d47da84503c93e3a1b0e7, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.129506 16393 consensus_queue.cc:260] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [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: "a8820627e52d47da84503c93e3a1b0e7" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 38863 } }
I20260812 06:17:10.129662 16393 raft_consensus.cc:399] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.129711 16393 raft_consensus.cc:493] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.129761 16393 raft_consensus.cc:3060] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.130528 16393 raft_consensus.cc:515] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8820627e52d47da84503c93e3a1b0e7" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 38863 } }
I20260812 06:17:10.130651 16393 leader_election.cc:304] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [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: a8820627e52d47da84503c93e3a1b0e7; no voters: 
I20260812 06:17:10.130824 16393 leader_election.cc:290] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.130987 16397 raft_consensus.cc:2804] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.131090 16397 raft_consensus.cc:697] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 1 LEADER]: Becoming Leader. State: Replica: a8820627e52d47da84503c93e3a1b0e7, State: Running, Role: LEADER
I20260812 06:17:10.131088 16393 ts_tablet_manager.cc:1434] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:10.131142 16360 heartbeater.cc:499] Master 127.15.100.254:35945 was elected leader, sending a full tablet report...
I20260812 06:17:10.131263 16397 consensus_queue.cc:237] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [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: "a8820627e52d47da84503c93e3a1b0e7" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 38863 } }
I20260812 06:17:10.132689 16127 catalog_manager.cc:5719] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 reported cstate change: term changed from 0 to 1, leader changed from <none> to a8820627e52d47da84503c93e3a1b0e7 (127.15.100.193). New cstate: current_term: 1 leader_uuid: "a8820627e52d47da84503c93e3a1b0e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8820627e52d47da84503c93e3a1b0e7" member_type: VOTER last_known_addr { host: "127.15.100.193" port: 38863 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:10.192119 15763 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:17:10.349390 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0): perf score=19.054940
I20260812 06:17:10.487396 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.138s	user 0.106s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":783,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33055,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":5376,"update_count":1500}
I20260812 06:17:10.488260 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling LogGCOp(db41e41b1cc44a34a5b693210a8828d0): free 20743880 bytes of WAL
I20260812 06:17:10.488533 16248 log_reader.cc:385] T db41e41b1cc44a34a5b693210a8828d0: removed 2 log segments from log reader
I20260812 06:17:10.488583 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000001 (ops 1-6)
I20260812 06:17:10.488626 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000002 (ops 7-11)
I20260812 06:17:10.492265 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: LogGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:10.492875 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:10.506524 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.507085 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:10.661523 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.154s	user 0.106s	sys 0.042s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303018,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":650,"lbm_read_time_us":10520,"lbm_reads_lt_1ms":454,"lbm_write_time_us":24037,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":316,"threads_started":5,"update_count":1950}
I20260812 06:17:10.662220 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0): 16821647 bytes on disk
I20260812 06:17:10.662706 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.663264 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=11.118625
I20260812 06:17:10.701536 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.038s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15967,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:10.702171 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:10.723033 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.021s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.723560 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:10.742062 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3357,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.742561 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:10.930751 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.188s	user 0.124s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":232,"lbm_read_time_us":12290,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29474,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:10.931310 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=11.118625
I20260812 06:17:10.961475 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.030s	user 0.013s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12228,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:10.962201 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:10.977068 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.977572 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:11.113715 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.136s	user 0.106s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":8775,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25201,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:11.114326 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:11.150803 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.036s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13608,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.151310 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:11.161631 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.162261 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:11.295616 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.133s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":724,"lbm_read_time_us":8277,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24958,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:17:11.296397 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:11.328001 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.031s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13294,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.328575 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:11.339457 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.340095 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:11.466142 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.126s	user 0.088s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":916,"lbm_read_time_us":8441,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24118,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":64896,"update_count":2000}
I20260812 06:17:11.466787 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:11.519891 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.053s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17025,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.520458 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:11.531481 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.532145 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:11.679096 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.146s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":11468,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21320,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:11.679739 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:11.717428 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.037s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16169,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.717965 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:11.728662 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.729462 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:11.757259 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1565,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1374,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:11.758030 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling LogGCOp(db41e41b1cc44a34a5b693210a8828d0): free 112239257 bytes of WAL
I20260812 06:17:11.758262 16248 log_reader.cc:385] T db41e41b1cc44a34a5b693210a8828d0: removed 11 log segments from log reader
I20260812 06:17:11.758309 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000003 (ops 12-16)
I20260812 06:17:11.758349 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000004 (ops 17-21)
I20260812 06:17:11.758383 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000005 (ops 22-26)
I20260812 06:17:11.758416 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000006 (ops 27-31)
I20260812 06:17:11.758447 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000007 (ops 32-36)
I20260812 06:17:11.758478 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000008 (ops 37-40)
I20260812 06:17:11.758502 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000009 (ops 41-45)
I20260812 06:17:11.758533 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000010 (ops 46-50)
I20260812 06:17:11.758563 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000011 (ops 51-55)
I20260812 06:17:11.758594 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000012 (ops 56-60)
I20260812 06:17:11.758623 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000013 (ops 61-65)
I20260812 06:17:11.780664 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: LogGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.022s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:11.781128 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=3.181125
I20260812 06:17:11.804158 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.023s	user 0.014s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:11.804693 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling LogGCOp(db41e41b1cc44a34a5b693210a8828d0): free 12017983 bytes of WAL
I20260812 06:17:11.804939 16248 log_reader.cc:385] T db41e41b1cc44a34a5b693210a8828d0: removed 1 log segments from log reader
I20260812 06:17:11.805015 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000014 (ops 66-70)
I20260812 06:17:11.807230 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: LogGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:11.807570 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0): 448 bytes on disk
I20260812 06:17:11.808029 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.808573 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:11.818673 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3609,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.819140 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:12.014978 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.196s	user 0.120s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14573,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29935,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":115,"threads_started":1,"update_count":3000}
I20260812 06:17:12.015758 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=14.095187
I20260812 06:17:12.068439 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.051s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17962,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.069046 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:12.080824 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.082732 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:12.263219 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.180s	user 0.107s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":708,"lbm_read_time_us":11255,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27249,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:12.263741 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=14.095187
I20260812 06:17:12.311034 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.047s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.311594 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:12.335611 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.024s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.336211 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:12.516914 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.180s	user 0.143s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":10918,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27047,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.517509 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=14.095187
I20260812 06:17:12.569438 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.052s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.570122 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:12.581687 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.582358 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:12.769802 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.187s	user 0.103s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":11944,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26827,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":109312,"update_count":2500}
I20260812 06:17:12.770351 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=14.095187
I20260812 06:17:12.818467 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.048s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.819129 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:12.831048 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4421,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.831743 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:12.979211 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.147s	user 0.095s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":820,"lbm_read_time_us":9150,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25257,"lbm_writes_lt_1ms":543,"mutex_wait_us":385,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:12.979955 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=14.095187
I20260812 06:17:13.031658 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.052s	user 0.011s	sys 0.033s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20873,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.032249 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:13.043098 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.043828 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:13.186017 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.142s	user 0.110s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":10022,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28890,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:17:13.186743 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=11.118625
I20260812 06:17:13.231011 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.044s	user 0.008s	sys 0.031s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18204,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.231542 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:13.245820 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4111,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.246459 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:13.302006 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.055s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1244,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1731,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":18688}
I20260812 06:17:13.302821 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling LogGCOp(db41e41b1cc44a34a5b693210a8828d0): free 121459497 bytes of WAL
I20260812 06:17:13.303109 16248 log_reader.cc:385] T db41e41b1cc44a34a5b693210a8828d0: removed 12 log segments from log reader
I20260812 06:17:13.303174 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000015 (ops 71-75)
I20260812 06:17:13.303217 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000016 (ops 76-80)
I20260812 06:17:13.303252 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000017 (ops 81-85)
I20260812 06:17:13.303275 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000018 (ops 86-90)
I20260812 06:17:13.303297 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000019 (ops 91-95)
I20260812 06:17:13.303329 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000020 (ops 96-100)
I20260812 06:17:13.303364 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000021 (ops 101-105)
I20260812 06:17:13.303391 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000022 (ops 106-110)
I20260812 06:17:13.303431 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000023 (ops 111-115)
I20260812 06:17:13.303457 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000024 (ops 116-120)
I20260812 06:17:13.303488 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000025 (ops 121-125)
I20260812 06:17:13.303517 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000026 (ops 126-130)
I20260812 06:17:13.330241 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: LogGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:13.330687 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0): 492 bytes on disk
I20260812 06:17:13.331125 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.331666 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=7.149875
I20260812 06:17:13.358624 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.027s	user 0.022s	sys 0.002s Metrics: {"bytes_written":9189657,"delete_count":0,"lbm_write_time_us":10468,"lbm_writes_lt_1ms":227,"reinsert_count":0,"update_count":1120}
I20260812 06:17:13.359264 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.196750
I20260812 06:17:13.373032 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.013s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3282,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:13.373538 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:13.567236 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.194s	user 0.124s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020713,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":7640,"dirs.run_cpu_time_us":497,"dirs.run_wall_time_us":4048,"lbm_read_time_us":12975,"lbm_reads_lt_1ms":766,"lbm_write_time_us":37660,"lbm_writes_lt_1ms":743,"mutex_wait_us":31,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":3500}
I20260812 06:17:13.567910 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=15.087375
I20260812 06:17:13.611019 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.043s	user 0.018s	sys 0.021s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":18147,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:13.611544 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:13.636289 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4259,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.636773 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:13.652760 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.653395 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:13.822248 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.169s	user 0.140s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918200,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1074,"lbm_read_time_us":11394,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35453,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:13.822806 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=14.095187
I20260812 06:17:13.871381 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.048s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18625,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.872017 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:13.882617 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.883162 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:14.040946 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.158s	user 0.115s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":12328,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28537,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:17:14.041620 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:14.073490 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.031s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13790,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.074033 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:14.091434 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.091961 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:14.235867 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.144s	user 0.115s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":10277,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22799,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:17:14.236521 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:14.273641 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.037s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16086,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.274184 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:14.285913 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.286541 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:14.431162 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.144s	user 0.090s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":957,"lbm_read_time_us":8670,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22560,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:17:14.431857 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=11.118625
I20260812 06:17:14.478078 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.046s	user 0.014s	sys 0.025s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18863,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:14.478689 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:14.490556 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.491087 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:14.500589 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3259,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.501091 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:14.648690 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.147s	user 0.109s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":707,"lbm_read_time_us":9144,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30922,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:17:14.649746 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:14.695544 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.046s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20367,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.696177 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=2.188937
I20260812 06:17:14.712819 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.713286 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:14.741660 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushMRSOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1497,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1861,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:14.742400 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling LogGCOp(db41e41b1cc44a34a5b693210a8828d0): free 124257509 bytes of WAL
I20260812 06:17:14.742653 16248 log_reader.cc:385] T db41e41b1cc44a34a5b693210a8828d0: removed 12 log segments from log reader
I20260812 06:17:14.742713 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000027 (ops 131-135)
I20260812 06:17:14.742760 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000028 (ops 136-140)
I20260812 06:17:14.742790 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000029 (ops 141-145)
I20260812 06:17:14.742816 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000030 (ops 146-150)
I20260812 06:17:14.742846 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000031 (ops 151-154)
I20260812 06:17:14.742875 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000032 (ops 155-159)
I20260812 06:17:14.742903 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000033 (ops 160-164)
I20260812 06:17:14.742936 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000034 (ops 165-169)
I20260812 06:17:14.742974 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000035 (ops 170-174)
I20260812 06:17:14.743011 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000036 (ops 175-179)
I20260812 06:17:14.743046 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000037 (ops 180-184)
I20260812 06:17:14.743084 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000038 (ops 185-189)
I20260812 06:17:14.766934 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: LogGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:14.767478 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=3.181125
I20260812 06:17:14.781672 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5087238,"delete_count":0,"lbm_write_time_us":5231,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:17:14.782214 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling LogGCOp(db41e41b1cc44a34a5b693210a8828d0): free 12017954 bytes of WAL
I20260812 06:17:14.782444 16248 log_reader.cc:385] T db41e41b1cc44a34a5b693210a8828d0: removed 1 log segments from log reader
I20260812 06:17:14.782503 16248 log.cc:1079] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: Deleting log segment in path: /tmp/dist-test-taskaGzsuZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424851223-15763-0/minicluster-data/ts-0-root/wals/db41e41b1cc44a34a5b693210a8828d0/wal-000000039 (ops 190-194)
I20260812 06:17:14.785248 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: LogGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:14.785670 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0): 472 bytes on disk
I20260812 06:17:14.786165 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: UndoDeltaBlockGCOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.786836 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.196750
I20260812 06:17:14.800665 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":4611,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:14.801174 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0): perf score=1.000000
I20260812 06:17:14.909361 15763 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.717s	user 1.755s	sys 0.145s
I20260812 06:17:14.952189 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: MajorDeltaCompactionOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.151s	user 0.109s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918309,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":11527,"lbm_reads_lt_1ms":662,"lbm_write_time_us":29145,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":3000}
I20260812 06:17:14.952907 16362 maintenance_manager.cc:419] P a8820627e52d47da84503c93e3a1b0e7: Scheduling FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0): perf score=10.126437
I20260812 06:17:14.977530 15763 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.068s	user 0.002s	sys 0.000s
I20260812 06:17:14.978154 15763 tablet_server.cc:179] TabletServer@127.15.100.193:0 shutting down...
I20260812 06:17:14.983259 16248 maintenance_manager.cc:643] P a8820627e52d47da84503c93e3a1b0e7: FlushDeltaMemStoresOp(db41e41b1cc44a34a5b693210a8828d0) complete. Timing: real 0.030s	user 0.022s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12478,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.983757 15763 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:14.983951 15763 tablet_replica.cc:333] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7: stopping tablet replica
I20260812 06:17:14.984072 15763 raft_consensus.cc:2243] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.984234 15763 raft_consensus.cc:2272] T db41e41b1cc44a34a5b693210a8828d0 P a8820627e52d47da84503c93e3a1b0e7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.997625 15763 tablet_server.cc:196] TabletServer@127.15.100.193:0 shutdown complete.
I20260812 06:17:15.010795 15763 master.cc:562] Master@127.15.100.254:35945 shutting down...
I20260812 06:17:15.014189 15763 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.014367 15763 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.014444 15763 tablet_replica.cc:333] T 00000000000000000000000000000000 P e71d10ae12ab4da6b220f94e3d35b0e9: stopping tablet replica
I20260812 06:17:15.027127 15763 master.cc:584] Master@127.15.100.254:35945 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5116 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10241 ms total)

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