[==========] 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:18:39.077291 32015 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.67.254:36627
I20260812 06:18:39.078401 32015 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:18:39.079082 32015 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.086024 32022 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:18:39.086061 32021 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:18:39.086302 32027 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:18:39.086444 32015 server_base.cc:1061] running on GCE node
I20260812 06:18:39.086931 32015 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.087090 32015 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:18:39.087152 32015 hybrid_clock.cc:648] HybridClock initialized: now 1786515519087148 us; error 0 us; skew 500 ppm
I20260812 06:18:39.089120 32015 webserver.cc:533] Webserver started at http://127.31.67.254:33813/ using document root <none> and password file <none>
I20260812 06:18:39.089709 32015 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.089804 32015 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.090078 32015 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.091753 32015 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/master-0-root/instance:
uuid: "851fb525c9044d8e9a5f4e6d21676902"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-10pc"
I20260812 06:18:39.095392 32015 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:39.097707 32034 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:18:39.098735 32015 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:39.098875 32015 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/master-0-root
uuid: "851fb525c9044d8e9a5f4e6d21676902"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-10pc"
I20260812 06:18:39.098984 32015 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-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:18:39.121631 32015 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:39.122305 32015 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:18:39.122496 32015 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:39.130314 32015 rpc_server.cc:307] RPC server started. Bound to: 127.31.67.254:36627
I20260812 06:18:39.130324 32093 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.67.254:36627 every 8 connection(s)
I20260812 06:18:39.132648 32094 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:18:39.138056 32094 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902: Bootstrap starting.
I20260812 06:18:39.140347 32094 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.141278 32094 log.cc:826] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:39.142926 32094 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902: No bootstrap required, opened a new log
I20260812 06:18:39.145776 32094 raft_consensus.cc:359] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "851fb525c9044d8e9a5f4e6d21676902" member_type: VOTER }
I20260812 06:18:39.145937 32094 raft_consensus.cc:385] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.146025 32094 raft_consensus.cc:740] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 851fb525c9044d8e9a5f4e6d21676902, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.146701 32094 consensus_queue.cc:260] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [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: "851fb525c9044d8e9a5f4e6d21676902" member_type: VOTER }
I20260812 06:18:39.146845 32094 raft_consensus.cc:399] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.146888 32094 raft_consensus.cc:493] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.147030 32094 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.147827 32094 raft_consensus.cc:515] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "851fb525c9044d8e9a5f4e6d21676902" member_type: VOTER }
I20260812 06:18:39.148298 32094 leader_election.cc:304] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [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: 851fb525c9044d8e9a5f4e6d21676902; no voters: 
I20260812 06:18:39.148636 32094 leader_election.cc:290] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.148825 32097 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.149129 32097 raft_consensus.cc:697] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 1 LEADER]: Becoming Leader. State: Replica: 851fb525c9044d8e9a5f4e6d21676902, State: Running, Role: LEADER
I20260812 06:18:39.149529 32097 consensus_queue.cc:237] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [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: "851fb525c9044d8e9a5f4e6d21676902" member_type: VOTER }
I20260812 06:18:39.149719 32094 sys_catalog.cc:565] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:39.151572 32101 sys_catalog.cc:455] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 851fb525c9044d8e9a5f4e6d21676902. Latest consensus state: current_term: 1 leader_uuid: "851fb525c9044d8e9a5f4e6d21676902" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "851fb525c9044d8e9a5f4e6d21676902" member_type: VOTER } }
I20260812 06:18:39.151719 32101 sys_catalog.cc:458] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.152050 32115 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:39.152112 32015 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:39.152014 32099 sys_catalog.cc:455] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "851fb525c9044d8e9a5f4e6d21676902" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "851fb525c9044d8e9a5f4e6d21676902" member_type: VOTER } }
I20260812 06:18:39.152186 32099 sys_catalog.cc:458] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.154675 32115 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:39.160029 32115 catalog_manager.cc:1383] Generated new cluster ID: 09eeffb893a444e79b8cbf9d04d7a67e
I20260812 06:18:39.160133 32115 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:39.170326 32115 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:39.171204 32115 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:39.178350 32115 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902: Generated new TSK 0
I20260812 06:18:39.178978 32115 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:39.184684 32015 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.187484 32124 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:18:39.187594 32121 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:18:39.187479 32120 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:18:39.187775 32015 server_base.cc:1061] running on GCE node
I20260812 06:18:39.188027 32015 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.188094 32015 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:18:39.188122 32015 hybrid_clock.cc:648] HybridClock initialized: now 1786515519188120 us; error 0 us; skew 500 ppm
I20260812 06:18:39.189123 32015 webserver.cc:533] Webserver started at http://127.31.67.193:40061/ using document root <none> and password file <none>
I20260812 06:18:39.189308 32015 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.189378 32015 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.189459 32015 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.189863 32015 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/instance:
uuid: "890ef341cf60433c846582843cd58cc4"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-10pc"
I20260812 06:18:39.191423 32015 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:18:39.192420 32129 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:18:39.192689 32015 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:39.192782 32015 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root
uuid: "890ef341cf60433c846582843cd58cc4"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-10pc"
I20260812 06:18:39.192854 32015 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-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:18:39.218163 32015 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:39.218710 32015 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:39.219255 32015 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:39.220243 32015 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:39.220328 32015 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.220414 32015 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:39.220494 32015 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.001s
I20260812 06:18:39.227818 32015 rpc_server.cc:307] RPC server started. Bound to: 127.31.67.193:38315
I20260812 06:18:39.227864 32199 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.67.193:38315 every 8 connection(s)
I20260812 06:18:39.242762 32200 heartbeater.cc:344] Connected to a master server at 127.31.67.254:36627
I20260812 06:18:39.243124 32200 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:39.243664 32200 heartbeater.cc:507] Master 127.31.67.254:36627 requested a full tablet report, sending...
I20260812 06:18:39.245283 32053 ts_manager.cc:194] Registered new tserver with Master: 890ef341cf60433c846582843cd58cc4 (127.31.67.193:38315)
I20260812 06:18:39.245481 32015 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016925734s
I20260812 06:18:39.246827 32053 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57790
I20260812 06:18:39.255825 32053 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57798:
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:18:39.271426 32160 tablet_service.cc:1511] Processing CreateTablet for tablet b62b709e1d5a473b8170360047066391 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cedb3a9a17be48f0a74438ce47f757a8]), partition=
I20260812 06:18:39.271919 32160 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b62b709e1d5a473b8170360047066391. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:39.274722 32214 tablet_bootstrap.cc:492] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Bootstrap starting.
I20260812 06:18:39.275832 32214 tablet_bootstrap.cc:654] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.277004 32214 tablet_bootstrap.cc:492] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: No bootstrap required, opened a new log
I20260812 06:18:39.277119 32214 ts_tablet_manager.cc:1403] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:39.277524 32214 raft_consensus.cc:359] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "890ef341cf60433c846582843cd58cc4" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 38315 } }
I20260812 06:18:39.277621 32214 raft_consensus.cc:385] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.277645 32214 raft_consensus.cc:740] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 890ef341cf60433c846582843cd58cc4, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.277832 32214 consensus_queue.cc:260] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [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: "890ef341cf60433c846582843cd58cc4" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 38315 } }
I20260812 06:18:39.277904 32214 raft_consensus.cc:399] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.277951 32214 raft_consensus.cc:493] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.278004 32214 raft_consensus.cc:3060] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.278713 32214 raft_consensus.cc:515] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "890ef341cf60433c846582843cd58cc4" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 38315 } }
I20260812 06:18:39.278879 32214 leader_election.cc:304] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [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: 890ef341cf60433c846582843cd58cc4; no voters: 
I20260812 06:18:39.279127 32214 leader_election.cc:290] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.279215 32216 raft_consensus.cc:2804] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.279489 32216 raft_consensus.cc:697] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 1 LEADER]: Becoming Leader. State: Replica: 890ef341cf60433c846582843cd58cc4, State: Running, Role: LEADER
I20260812 06:18:39.279567 32214 ts_tablet_manager.cc:1434] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:39.279744 32200 heartbeater.cc:499] Master 127.31.67.254:36627 was elected leader, sending a full tablet report...
I20260812 06:18:39.280066 32216 consensus_queue.cc:237] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [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: "890ef341cf60433c846582843cd58cc4" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 38315 } }
I20260812 06:18:39.282737 32053 catalog_manager.cc:5719] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 890ef341cf60433c846582843cd58cc4 (127.31.67.193). New cstate: current_term: 1 leader_uuid: "890ef341cf60433c846582843cd58cc4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "890ef341cf60433c846582843cd58cc4" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 38315 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:39.348623 32015 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.012s
I20260812 06:18:39.479038 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushMRSOp(b62b709e1d5a473b8170360047066391): perf score=19.054940
I20260812 06:18:39.654886 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushMRSOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.175s	user 0.113s	sys 0.059s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":194,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":834,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45167,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":131,"threads_started":1,"update_count":1500}
I20260812 06:18:39.656163 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling LogGCOp(b62b709e1d5a473b8170360047066391): free 20743880 bytes of WAL
I20260812 06:18:39.656505 32134 log_reader.cc:385] T b62b709e1d5a473b8170360047066391: removed 2 log segments from log reader
I20260812 06:18:39.656589 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000001 (ops 1-6)
I20260812 06:18:39.656702 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000002 (ops 7-11)
I20260812 06:18:39.662703 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: LogGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:39.663094 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391): 16411396 bytes on disk
I20260812 06:18:39.663739 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.664215 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:39.682716 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.018s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":500}
I20260812 06:18:39.683346 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:39.835141 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.152s	user 0.108s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1785,"lbm_read_time_us":7708,"lbm_reads_lt_1ms":460,"lbm_write_time_us":27545,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":412,"threads_started":5,"update_count":2000}
I20260812 06:18:39.835834 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=10.126437
I20260812 06:18:39.879542 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.044s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17655,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.880052 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:39.894290 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.894824 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:40.025501 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.130s	user 0.115s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":7813,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25873,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32896,"update_count":2000}
I20260812 06:18:40.026105 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=10.126437
I20260812 06:18:40.064152 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.038s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16305,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.064790 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:40.077216 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.077797 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:40.209146 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.131s	user 0.095s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1033,"lbm_read_time_us":9616,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26022,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.209803 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=10.126437
I20260812 06:18:40.264832 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.055s	user 0.020s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17123,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.265427 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:40.282065 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.282711 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:40.439043 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.156s	user 0.106s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":249,"lbm_read_time_us":12473,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25161,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:18:40.439795 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=10.126437
I20260812 06:18:40.486037 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.046s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14936,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.486550 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:40.503518 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.504179 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:40.624361 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.120s	user 0.104s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":8417,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22366,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:40.625146 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=10.126437
I20260812 06:18:40.661896 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15678,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.662613 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:40.674609 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.675055 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:40.793062 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.118s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":65,"lbm_read_time_us":8725,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22630,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:18:40.793718 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=10.126437
I20260812 06:18:40.842526 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.049s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16145,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.843142 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:40.854686 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.855139 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushMRSOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:40.902169 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushMRSOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.047s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1384,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1462,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:40.903043 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling LogGCOp(b62b709e1d5a473b8170360047066391): free 108535449 bytes of WAL
I20260812 06:18:40.903321 32134 log_reader.cc:385] T b62b709e1d5a473b8170360047066391: removed 11 log segments from log reader
I20260812 06:18:40.903371 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000003 (ops 12-16)
I20260812 06:18:40.903401 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000004 (ops 17-20)
I20260812 06:18:40.903461 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000005 (ops 21-25)
I20260812 06:18:40.903523 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000006 (ops 26-30)
I20260812 06:18:40.903561 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000007 (ops 31-34)
I20260812 06:18:40.903600 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000008 (ops 35-39)
I20260812 06:18:40.903640 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000009 (ops 40-44)
I20260812 06:18:40.903677 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000010 (ops 45-49)
I20260812 06:18:40.903715 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000011 (ops 50-54)
I20260812 06:18:40.903754 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000012 (ops 55-59)
I20260812 06:18:40.903792 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000013 (ops 60-64)
I20260812 06:18:40.928253 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: LogGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:40.928679 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391): 448 bytes on disk
I20260812 06:18:40.929531 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.930183 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=3.181125
I20260812 06:18:40.951825 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.021s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":6787,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:18:40.952301 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:40.966289 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3815483,"delete_count":0,"lbm_write_time_us":5363,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:40.967080 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:41.184880 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.218s	user 0.129s	sys 0.087s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877335,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1738,"lbm_read_time_us":15380,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36558,"lbm_writes_lt_1ms":643,"mutex_wait_us":1309,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:18:41.185708 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:41.238957 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.053s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.239506 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:41.398102 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.158s	user 0.110s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":317,"lbm_read_time_us":10094,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23316,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":45952,"update_count":2000}
I20260812 06:18:41.398800 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:41.450208 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.051s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19519,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.450647 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:41.463408 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4481,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.463903 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:41.653638 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.189s	user 0.114s	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":290,"lbm_read_time_us":11563,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26458,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:41.654274 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:41.712800 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.058s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.713335 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:41.724258 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.724902 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:41.878544 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.153s	user 0.123s	sys 0.027s 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":1351,"lbm_read_time_us":9766,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30655,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:41.879217 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=11.118625
I20260812 06:18:41.914427 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14793,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:41.915045 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:41.937240 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.022s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.937700 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:41.947293 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3497,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.947799 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:42.091018 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.143s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":627,"lbm_read_time_us":9813,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29602,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":632192,"update_count":2500}
I20260812 06:18:42.091764 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=11.118625
I20260812 06:18:42.134954 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.043s	user 0.025s	sys 0.010s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15339,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:42.135588 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:42.148698 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.149132 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:42.159641 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.160105 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:42.314592 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.154s	user 0.123s	sys 0.028s 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":318,"lbm_read_time_us":9099,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32715,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:42.315336 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=11.118625
I20260812 06:18:42.353715 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.038s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16477,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:42.354559 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:42.370653 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5380,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.371116 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushMRSOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:42.421518 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushMRSOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.050s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":1347,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2402,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:42.422268 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling LogGCOp(b62b709e1d5a473b8170360047066391): free 124257199 bytes of WAL
I20260812 06:18:42.422506 32134 log_reader.cc:385] T b62b709e1d5a473b8170360047066391: removed 12 log segments from log reader
I20260812 06:18:42.422554 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000014 (ops 65-69)
I20260812 06:18:42.422583 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000015 (ops 70-74)
I20260812 06:18:42.422643 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000016 (ops 75-79)
I20260812 06:18:42.422686 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000017 (ops 80-84)
I20260812 06:18:42.422748 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000018 (ops 85-88)
I20260812 06:18:42.422778 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000019 (ops 89-93)
I20260812 06:18:42.422821 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000020 (ops 94-98)
I20260812 06:18:42.422864 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000021 (ops 99-103)
I20260812 06:18:42.422904 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000022 (ops 104-108)
I20260812 06:18:42.422945 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000023 (ops 109-113)
I20260812 06:18:42.422986 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000024 (ops 114-118)
I20260812 06:18:42.423025 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000025 (ops 119-123)
I20260812 06:18:42.448750 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: LogGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:42.449163 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=6.157687
I20260812 06:18:42.476172 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.027s	user 0.018s	sys 0.006s Metrics: {"bytes_written":8246103,"delete_count":0,"lbm_write_time_us":11598,"lbm_writes_lt_1ms":204,"reinsert_count":0,"update_count":1005}
I20260812 06:18:42.476725 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling LogGCOp(b62b709e1d5a473b8170360047066391): free 8767174 bytes of WAL
I20260812 06:18:42.476946 32134 log_reader.cc:385] T b62b709e1d5a473b8170360047066391: removed 1 log segments from log reader
I20260812 06:18:42.476994 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000026 (ops 124-128)
I20260812 06:18:42.478710 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: LogGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:42.479020 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391): 482 bytes on disk
I20260812 06:18:42.479405 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.479876 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:42.495564 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":5080,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:42.496006 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:42.689543 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.193s	user 0.157s	sys 0.031s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":648,"lbm_read_time_us":12671,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39179,"lbm_writes_lt_1ms":743,"mutex_wait_us":177,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:42.690394 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=15.087375
I20260812 06:18:42.739392 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.048s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20452,"lbm_writes_lt_1ms":413,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2050}
I20260812 06:18:42.740123 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:42.761551 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.021s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.762013 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:42.771605 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3676,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.772076 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:42.939729 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.167s	user 0.139s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":223,"lbm_read_time_us":12394,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34083,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:18:42.940397 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:42.994619 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.054s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24957,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.995306 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.020421 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.025s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.021013 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.031318 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.031806 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:43.202052 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.170s	user 0.126s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":826,"lbm_read_time_us":11193,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38506,"lbm_writes_lt_1ms":643,"mutex_wait_us":275,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:18:43.202718 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:43.256800 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.054s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22438,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.257411 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.273562 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.274319 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:43.440366 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.166s	user 0.115s	sys 0.039s 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":562,"lbm_read_time_us":9481,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30135,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:18:43.441108 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:43.507431 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.066s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25235,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.507910 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.519104 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4046,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.519676 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:43.681588 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.162s	user 0.122s	sys 0.036s 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":165,"lbm_read_time_us":12556,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26103,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:43.682317 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=14.095187
I20260812 06:18:43.739460 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.057s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21849,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.740047 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.751024 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.751569 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushMRSOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:43.791297 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushMRSOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.040s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1390,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1469,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:43.792068 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling LogGCOp(b62b709e1d5a473b8170360047066391): free 123804449 bytes of WAL
I20260812 06:18:43.792356 32134 log_reader.cc:385] T b62b709e1d5a473b8170360047066391: removed 12 log segments from log reader
I20260812 06:18:43.792425 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000027 (ops 129-132)
I20260812 06:18:43.792492 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000028 (ops 133-137)
I20260812 06:18:43.792526 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000029 (ops 138-142)
I20260812 06:18:43.792554 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000030 (ops 143-147)
I20260812 06:18:43.792585 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000031 (ops 148-152)
I20260812 06:18:43.792619 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000032 (ops 153-156)
I20260812 06:18:43.792645 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000033 (ops 157-161)
I20260812 06:18:43.792675 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000034 (ops 162-166)
I20260812 06:18:43.792703 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000035 (ops 167-171)
I20260812 06:18:43.792733 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000036 (ops 172-176)
I20260812 06:18:43.792762 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000037 (ops 177-181)
I20260812 06:18:43.792796 32134 log.cc:1079] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/b62b709e1d5a473b8170360047066391/wal-000000038 (ops 182-186)
I20260812 06:18:43.823357 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: LogGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:43.823766 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391): 465 bytes on disk
I20260812 06:18:43.824218 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: UndoDeltaBlockGCOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.824843 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.846362 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.021s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.846911 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=2.188937
I20260812 06:18:43.857643 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4123,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.858111 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:44.064441 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.206s	user 0.160s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":384,"lbm_read_time_us":14762,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37774,"lbm_writes_lt_1ms":743,"mutex_wait_us":43,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:44.065140 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=15.087375
I20260812 06:18:44.115453 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.050s	user 0.039s	sys 0.003s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":19024,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:44.116005 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=4.173312
I20260812 06:18:44.124846 32015 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.776s	user 1.798s	sys 0.133s
I20260812 06:18:44.129498 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":5374413,"delete_count":0,"lbm_write_time_us":5846,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:18:44.129911 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391): perf score=1.196750
I20260812 06:18:44.136390 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: FlushDeltaMemStoresOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":2345,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:18:44.136813 32201 maintenance_manager.cc:419] P 890ef341cf60433c846582843cd58cc4: Scheduling MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391): perf score=1.000000
I20260812 06:18:44.177366 32015 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.005s	sys 0.000s
I20260812 06:18:44.178124 32015 tablet_server.cc:179] TabletServer@127.31.67.193:0 shutting down...
I20260812 06:18:44.282073 32134 maintenance_manager.cc:643] P 890ef341cf60433c846582843cd58cc4: MajorDeltaCompactionOp(b62b709e1d5a473b8170360047066391) complete. Timing: real 0.145s	user 0.085s	sys 0.059s Metrics: {"cfile_cache_hit":296,"cfile_cache_hit_bytes":12103745,"cfile_cache_miss":337,"cfile_cache_miss_bytes":16773435,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":746,"lbm_read_time_us":6233,"lbm_reads_lt_1ms":373,"lbm_write_time_us":30193,"lbm_writes_lt_1ms":643,"mutex_wait_us":268,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":3000}
I20260812 06:18:44.282743 32015 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:44.283161 32015 tablet_replica.cc:333] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4: stopping tablet replica
I20260812 06:18:44.283411 32015 raft_consensus.cc:2243] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:44.283658 32015 raft_consensus.cc:2272] T b62b709e1d5a473b8170360047066391 P 890ef341cf60433c846582843cd58cc4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:44.298945 32015 tablet_server.cc:196] TabletServer@127.31.67.193:0 shutdown complete.
I20260812 06:18:44.335340 32015 master.cc:562] Master@127.31.67.254:36627 shutting down...
I20260812 06:18:44.338835 32015 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:44.339037 32015 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:44.339126 32015 tablet_replica.cc:333] T 00000000000000000000000000000000 P 851fb525c9044d8e9a5f4e6d21676902: stopping tablet replica
I20260812 06:18:44.351650 32015 master.cc:584] Master@127.31.67.254:36627 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5364 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:44.441191 32015 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.67.254:39677
I20260812 06:18:44.441607 32015 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:44.444223 32015 server_base.cc:1061] running on GCE node
W20260812 06:18:44.444262 32240 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:18:44.444361 32238 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:18:44.444370 32237 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:18:44.444698 32015 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:44.444743 32015 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:18:44.444759 32015 hybrid_clock.cc:648] HybridClock initialized: now 1786515524444759 us; error 0 us; skew 500 ppm
I20260812 06:18:44.445636 32015 webserver.cc:533] Webserver started at http://127.31.67.254:35487/ using document root <none> and password file <none>
I20260812 06:18:44.445812 32015 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:44.445858 32015 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:44.445955 32015 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:44.446378 32015 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/master-0-root/instance:
uuid: "5bf325edc0004f55905331ed2a6f4c34"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-10pc"
I20260812 06:18:44.447925 32015 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:44.448923 32246 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:18:44.449220 32015 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:44.449285 32015 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/master-0-root
uuid: "5bf325edc0004f55905331ed2a6f4c34"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-10pc"
I20260812 06:18:44.449375 32015 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-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:18:44.472345 32015 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:44.472801 32015 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:44.476889 32015 rpc_server.cc:307] RPC server started. Bound to: 127.31.67.254:39677
I20260812 06:18:44.479895 32307 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:18:44.483156 32306 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.67.254:39677 every 8 connection(s)
I20260812 06:18:44.487097 32307 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34: Bootstrap starting.
I20260812 06:18:44.487944 32307 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:44.488986 32307 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34: No bootstrap required, opened a new log
I20260812 06:18:44.489414 32307 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5bf325edc0004f55905331ed2a6f4c34" member_type: VOTER }
I20260812 06:18:44.489500 32307 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:44.489562 32307 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5bf325edc0004f55905331ed2a6f4c34, State: Initialized, Role: FOLLOWER
I20260812 06:18:44.489720 32307 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [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: "5bf325edc0004f55905331ed2a6f4c34" member_type: VOTER }
I20260812 06:18:44.489810 32307 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:44.489861 32307 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:44.489943 32307 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:44.490612 32307 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5bf325edc0004f55905331ed2a6f4c34" member_type: VOTER }
I20260812 06:18:44.490758 32307 leader_election.cc:304] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [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: 5bf325edc0004f55905331ed2a6f4c34; no voters: 
I20260812 06:18:44.490970 32307 leader_election.cc:290] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:44.491120 32310 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:44.491367 32310 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 1 LEADER]: Becoming Leader. State: Replica: 5bf325edc0004f55905331ed2a6f4c34, State: Running, Role: LEADER
I20260812 06:18:44.491420 32307 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:44.491529 32310 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [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: "5bf325edc0004f55905331ed2a6f4c34" member_type: VOTER }
I20260812 06:18:44.491961 32311 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5bf325edc0004f55905331ed2a6f4c34" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5bf325edc0004f55905331ed2a6f4c34" member_type: VOTER } }
I20260812 06:18:44.492069 32311 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:44.492290 32312 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5bf325edc0004f55905331ed2a6f4c34. Latest consensus state: current_term: 1 leader_uuid: "5bf325edc0004f55905331ed2a6f4c34" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5bf325edc0004f55905331ed2a6f4c34" member_type: VOTER } }
I20260812 06:18:44.492429 32312 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:44.492364 32316 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:44.493180 32316 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:44.493422 32015 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:44.494860 32316 catalog_manager.cc:1383] Generated new cluster ID: 57321e433b89498d924af7248cdde7dc
I20260812 06:18:44.494918 32316 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:44.505613 32316 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:44.506114 32316 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:44.510538 32316 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34: Generated new TSK 0
I20260812 06:18:44.510694 32316 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:44.525645 32015 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:44.527571 32331 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:18:44.527665 32334 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:18:44.527674 32332 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:18:44.527827 32015 server_base.cc:1061] running on GCE node
I20260812 06:18:44.528035 32015 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:44.528100 32015 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:18:44.528134 32015 hybrid_clock.cc:648] HybridClock initialized: now 1786515524528133 us; error 0 us; skew 500 ppm
I20260812 06:18:44.529054 32015 webserver.cc:533] Webserver started at http://127.31.67.193:39467/ using document root <none> and password file <none>
I20260812 06:18:44.529230 32015 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:44.529299 32015 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:44.529382 32015 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:44.529769 32015 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/instance:
uuid: "35fa9172a7624168a441a6a0e6e3582a"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-10pc"
I20260812 06:18:44.531324 32015 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:44.532212 32340 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:18:44.532536 32015 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:44.532625 32015 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root
uuid: "35fa9172a7624168a441a6a0e6e3582a"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-10pc"
I20260812 06:18:44.532713 32015 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-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:18:44.576169 32015 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:44.576663 32015 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:44.577028 32015 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:44.577558 32015 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:44.577628 32015 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:44.577690 32015 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:44.577741 32015 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:44.582047 32015 rpc_server.cc:307] RPC server started. Bound to: 127.31.67.193:36615
I20260812 06:18:44.583714 32414 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.67.193:36615 every 8 connection(s)
I20260812 06:18:44.593506 32415 heartbeater.cc:344] Connected to a master server at 127.31.67.254:39677
I20260812 06:18:44.593640 32415 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:44.593871 32415 heartbeater.cc:507] Master 127.31.67.254:39677 requested a full tablet report, sending...
I20260812 06:18:44.594558 32267 ts_manager.cc:194] Registered new tserver with Master: 35fa9172a7624168a441a6a0e6e3582a (127.31.67.193:36615)
I20260812 06:18:44.595293 32267 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35964
I20260812 06:18:44.595405 32015 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012347458s
I20260812 06:18:44.602150 32267 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35974:
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:18:44.610824 32374 tablet_service.cc:1511] Processing CreateTablet for tablet 5ecb0fa90f844dbab2f7f821cf8219bb (DEFAULT_TABLE table=heavy-update-compaction-test [id=7740f07c8c464ee98fba351fd6504a39]), partition=
I20260812 06:18:44.611150 32374 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5ecb0fa90f844dbab2f7f821cf8219bb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:44.613408 32429 tablet_bootstrap.cc:492] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Bootstrap starting.
I20260812 06:18:44.614229 32429 tablet_bootstrap.cc:654] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:44.615296 32429 tablet_bootstrap.cc:492] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: No bootstrap required, opened a new log
I20260812 06:18:44.615412 32429 ts_tablet_manager.cc:1403] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:44.615871 32429 raft_consensus.cc:359] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35fa9172a7624168a441a6a0e6e3582a" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 36615 } }
I20260812 06:18:44.616005 32429 raft_consensus.cc:385] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:44.616072 32429 raft_consensus.cc:740] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 35fa9172a7624168a441a6a0e6e3582a, State: Initialized, Role: FOLLOWER
I20260812 06:18:44.616216 32429 consensus_queue.cc:260] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [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: "35fa9172a7624168a441a6a0e6e3582a" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 36615 } }
I20260812 06:18:44.616341 32429 raft_consensus.cc:399] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:44.616394 32429 raft_consensus.cc:493] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:44.616470 32429 raft_consensus.cc:3060] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:44.617192 32429 raft_consensus.cc:515] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35fa9172a7624168a441a6a0e6e3582a" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 36615 } }
I20260812 06:18:44.617348 32429 leader_election.cc:304] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [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: 35fa9172a7624168a441a6a0e6e3582a; no voters: 
I20260812 06:18:44.617534 32429 leader_election.cc:290] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:44.617679 32431 raft_consensus.cc:2804] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:44.617905 32431 raft_consensus.cc:697] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 1 LEADER]: Becoming Leader. State: Replica: 35fa9172a7624168a441a6a0e6e3582a, State: Running, Role: LEADER
I20260812 06:18:44.617960 32415 heartbeater.cc:499] Master 127.31.67.254:39677 was elected leader, sending a full tablet report...
I20260812 06:18:44.618057 32431 consensus_queue.cc:237] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [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: "35fa9172a7624168a441a6a0e6e3582a" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 36615 } }
I20260812 06:18:44.618233 32429 ts_tablet_manager.cc:1434] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:44.619426 32267 catalog_manager.cc:5719] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a reported cstate change: term changed from 0 to 1, leader changed from <none> to 35fa9172a7624168a441a6a0e6e3582a (127.31.67.193). New cstate: current_term: 1 leader_uuid: "35fa9172a7624168a441a6a0e6e3582a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35fa9172a7624168a441a6a0e6e3582a" member_type: VOTER last_known_addr { host: "127.31.67.193" port: 36615 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:44.679096 32015 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.013s	sys 0.010s
I20260812 06:18:44.834254 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=19.054940
I20260812 06:18:44.996352 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.162s	user 0.120s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":908,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42370,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:44.997081 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): 16411396 bytes on disk
I20260812 06:18:44.997522 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) 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:18:44.997912 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:45.013201 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.013794 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): free 20743880 bytes of WAL
I20260812 06:18:45.014050 32345 log_reader.cc:385] T 5ecb0fa90f844dbab2f7f821cf8219bb: removed 2 log segments from log reader
I20260812 06:18:45.014112 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000001 (ops 1-6)
I20260812 06:18:45.014160 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000002 (ops 7-11)
I20260812 06:18:45.020352 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:45.020828 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:45.177428 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.156s	user 0.112s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":968,"lbm_read_time_us":12490,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24330,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":370,"threads_started":5,"update_count":2000}
I20260812 06:18:45.178126 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=10.126437
I20260812 06:18:45.225289 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.047s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15458,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:45.225772 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:45.242959 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.017s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5389,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.243450 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:45.406682 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.163s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1387,"lbm_read_time_us":9435,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26818,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":50944,"update_count":2000}
I20260812 06:18:45.407261 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:45.461716 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.054s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22161,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:45.462312 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:45.473480 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.474020 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:45.651081 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.177s	user 0.122s	sys 0.043s 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":260,"lbm_read_time_us":10249,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31130,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:45.651667 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:45.708878 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.057s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.709375 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:45.725107 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.725598 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:45.878408 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.153s	user 0.123s	sys 0.028s 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":1074,"lbm_read_time_us":9644,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31386,"lbm_writes_lt_1ms":543,"mutex_wait_us":447,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:45.879029 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=11.118625
I20260812 06:18:45.908514 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.029s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12668,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.909283 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:45.925426 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.925891 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:46.051064 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.125s	user 0.092s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":746,"lbm_read_time_us":7318,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26563,"lbm_writes_lt_1ms":443,"mutex_wait_us":280,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:46.052040 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=10.126437
I20260812 06:18:46.095211 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.043s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15893,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.095770 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:46.106462 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.107267 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:46.240046 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.133s	user 0.090s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1036,"lbm_read_time_us":9800,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25217,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:18:46.240795 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=10.126437
I20260812 06:18:46.293370 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.052s	user 0.029s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16258,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.294023 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:46.305156 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.305627 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:46.349345 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.044s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1457,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1449,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:46.350014 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): free 124710243 bytes of WAL
I20260812 06:18:46.350253 32345 log_reader.cc:385] T 5ecb0fa90f844dbab2f7f821cf8219bb: removed 12 log segments from log reader
I20260812 06:18:46.350298 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000003 (ops 12-16)
I20260812 06:18:46.350327 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000004 (ops 17-21)
I20260812 06:18:46.350391 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000005 (ops 22-26)
I20260812 06:18:46.350435 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000006 (ops 27-31)
I20260812 06:18:46.350555 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000007 (ops 32-36)
I20260812 06:18:46.350579 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000008 (ops 37-41)
I20260812 06:18:46.350638 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000009 (ops 42-46)
I20260812 06:18:46.350680 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000010 (ops 47-51)
I20260812 06:18:46.350721 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000011 (ops 52-56)
I20260812 06:18:46.350761 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000012 (ops 57-61)
I20260812 06:18:46.350801 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000013 (ops 62-66)
I20260812 06:18:46.350841 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000014 (ops 67-71)
I20260812 06:18:46.378599 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:46.379031 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): 473 bytes on disk
I20260812 06:18:46.379561 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.380103 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=3.181125
I20260812 06:18:46.403059 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7240,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.403560 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:46.413646 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3801,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.414114 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:46.627903 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.214s	user 0.157s	sys 0.056s 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":319,"lbm_read_time_us":14482,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35149,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:18:46.629103 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=15.087375
I20260812 06:18:46.688961 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.060s	user 0.042s	sys 0.013s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":22704,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:46.689527 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:46.700827 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4225737,"delete_count":0,"lbm_write_time_us":4401,"lbm_writes_lt_1ms":106,"mutex_wait_us":92,"reinsert_count":0,"update_count":515}
I20260812 06:18:46.701248 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:46.710518 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":3455,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:18:46.711473 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:46.906787 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.195s	user 0.123s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":757,"lbm_read_time_us":14983,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32155,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":3000}
I20260812 06:18:46.908874 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:46.969676 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.060s	user 0.018s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26689,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.970214 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=3.181125
I20260812 06:18:46.983093 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.983608 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:46.994113 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.994542 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:47.191700 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.197s	user 0.149s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1051,"lbm_read_time_us":15630,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31617,"lbm_writes_lt_1ms":643,"mutex_wait_us":325,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":3000}
I20260812 06:18:47.192236 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:47.242690 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.050s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":22404,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.243377 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:47.266752 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.023s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.267448 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:47.447074 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.179s	user 0.117s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":14085,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29431,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:47.447824 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=15.087375
I20260812 06:18:47.505414 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.057s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":24489,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:47.505990 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:47.524806 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.019s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.525357 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:47.534931 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.535563 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:47.751350 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.216s	user 0.155s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":161,"lbm_read_time_us":15946,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36979,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:18:47.752017 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:47.815743 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.063s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24587,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.816282 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:47.827548 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.828022 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:47.858208 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1398,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:47.858860 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): free 124710369 bytes of WAL
I20260812 06:18:47.859088 32345 log_reader.cc:385] T 5ecb0fa90f844dbab2f7f821cf8219bb: removed 12 log segments from log reader
I20260812 06:18:47.859150 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000015 (ops 72-76)
I20260812 06:18:47.859201 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000016 (ops 77-81)
I20260812 06:18:47.859259 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000017 (ops 82-86)
I20260812 06:18:47.859304 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000018 (ops 87-91)
I20260812 06:18:47.859342 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000019 (ops 92-96)
I20260812 06:18:47.859382 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000020 (ops 97-101)
I20260812 06:18:47.859421 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000021 (ops 102-106)
I20260812 06:18:47.859462 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000022 (ops 107-111)
I20260812 06:18:47.859501 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000023 (ops 112-116)
I20260812 06:18:47.859547 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000024 (ops 117-121)
I20260812 06:18:47.859589 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000025 (ops 122-126)
I20260812 06:18:47.859625 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000026 (ops 127-131)
I20260812 06:18:47.888108 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:47.888620 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): 472 bytes on disk
I20260812 06:18:47.889812 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.890419 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=6.157687
I20260812 06:18:47.911501 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.021s	user 0.009s	sys 0.009s Metrics: {"bytes_written":7712789,"delete_count":0,"lbm_write_time_us":8628,"lbm_writes_lt_1ms":191,"reinsert_count":0,"update_count":940}
I20260812 06:18:47.912067 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:48.131989 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.220s	user 0.136s	sys 0.080s Metrics: {"cfile_cache_miss":721,"cfile_cache_miss_bytes":32487342,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":664,"lbm_read_time_us":15397,"lbm_reads_lt_1ms":753,"lbm_write_time_us":40166,"lbm_writes_lt_1ms":731,"mutex_wait_us":28,"peak_mem_usage":86436240,"reinsert_count":0,"thread_start_us":109,"threads_started":1,"update_count":3440}
I20260812 06:18:48.132854 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=19.056125
I20260812 06:18:48.196864 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.064s	user 0.031s	sys 0.032s Metrics: {"bytes_written":21004609,"delete_count":0,"lbm_write_time_us":27553,"lbm_writes_lt_1ms":515,"reinsert_count":0,"update_count":2560}
I20260812 06:18:48.197365 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=3.181125
I20260812 06:18:48.218928 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.021s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5008,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.219401 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:48.230192 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.230772 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:48.434376 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.203s	user 0.175s	sys 0.028s Metrics: {"cfile_cache_miss":745,"cfile_cache_miss_bytes":33471916,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":80,"lbm_read_time_us":14284,"lbm_reads_lt_1ms":785,"lbm_write_time_us":44877,"lbm_writes_lt_1ms":755,"mutex_wait_us":25,"peak_mem_usage":89501848,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3560}
I20260812 06:18:48.435073 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=15.087375
I20260812 06:18:48.482069 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.047s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":19542,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:48.482755 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:48.509016 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.509517 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:48.521488 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.522329 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:48.692090 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.169s	user 0.129s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":239,"lbm_read_time_us":10468,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37529,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:48.692672 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:48.746603 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.054s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21469,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.747066 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:48.759508 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.759940 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:48.928139 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.168s	user 0.113s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":11031,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30355,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:48.928885 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:48.992673 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.064s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24195,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.993150 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:49.005301 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.007825 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:49.202960 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.195s	user 0.134s	sys 0.055s 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":673,"lbm_read_time_us":13075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30963,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:18:49.203703 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:49.257242 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.053s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20308,"lbm_writes_lt_1ms":403,"mutex_wait_us":30,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.257861 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:49.296092 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushMRSOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.038s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1563,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1629,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:49.297214 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=3.181125
I20260812 06:18:49.311357 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.014s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4471879,"delete_count":0,"lbm_write_time_us":4482,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:18:49.311805 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): free 120553592 bytes of WAL
I20260812 06:18:49.312022 32345 log_reader.cc:385] T 5ecb0fa90f844dbab2f7f821cf8219bb: removed 12 log segments from log reader
I20260812 06:18:49.312068 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000027 (ops 132-136)
I20260812 06:18:49.312127 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000028 (ops 137-140)
I20260812 06:18:49.312172 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000029 (ops 141-145)
I20260812 06:18:49.312232 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000030 (ops 146-150)
I20260812 06:18:49.312266 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000031 (ops 151-155)
I20260812 06:18:49.312328 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000032 (ops 156-160)
I20260812 06:18:49.312367 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000033 (ops 161-165)
I20260812 06:18:49.312405 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000034 (ops 166-170)
I20260812 06:18:49.312443 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000035 (ops 171-175)
I20260812 06:18:49.312506 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000036 (ops 176-180)
I20260812 06:18:49.312546 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000037 (ops 181-184)
I20260812 06:18:49.312587 32345 log.cc:1079] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: Deleting log segment in path: /tmp/dist-test-taskvGscYO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515519065956-32015-0/minicluster-data/ts-0-root/wals/5ecb0fa90f844dbab2f7f821cf8219bb/wal-000000038 (ops 185-189)
I20260812 06:18:49.337697 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: LogGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:49.338212 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:49.356210 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.018s	user 0.007s	sys 0.002s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:49.356684 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=2.188937
I20260812 06:18:49.366852 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.367301 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb): 473 bytes on disk
I20260812 06:18:49.367713 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: UndoDeltaBlockGCOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.368613 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=1.000000
I20260812 06:18:49.560333 32015 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.881s	user 1.825s	sys 0.159s
I20260812 06:18:49.586319 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: MajorDeltaCompactionOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.217s	user 0.134s	sys 0.081s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16196,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38660,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3500}
I20260812 06:18:49.586822 32416 maintenance_manager.cc:419] P 35fa9172a7624168a441a6a0e6e3582a: Scheduling FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb): perf score=14.095187
I20260812 06:18:49.626852 32015 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.001s	sys 0.000s
I20260812 06:18:49.627337 32015 tablet_server.cc:179] TabletServer@127.31.67.193:0 shutting down...
I20260812 06:18:49.664423 32345 maintenance_manager.cc:643] P 35fa9172a7624168a441a6a0e6e3582a: FlushDeltaMemStoresOp(5ecb0fa90f844dbab2f7f821cf8219bb) complete. Timing: real 0.077s	user 0.017s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16208,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:49.665294 32015 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:49.665581 32015 tablet_replica.cc:333] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a: stopping tablet replica
I20260812 06:18:49.665750 32015 raft_consensus.cc:2243] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:49.665920 32015 raft_consensus.cc:2272] T 5ecb0fa90f844dbab2f7f821cf8219bb P 35fa9172a7624168a441a6a0e6e3582a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:49.669602 32015 tablet_server.cc:196] TabletServer@127.31.67.193:0 shutdown complete.
I20260812 06:18:49.684106 32015 master.cc:562] Master@127.31.67.254:39677 shutting down...
I20260812 06:18:49.688077 32015 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:49.688261 32015 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:49.688318 32015 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5bf325edc0004f55905331ed2a6f4c34: stopping tablet replica
I20260812 06:18:49.700806 32015 master.cc:584] Master@127.31.67.254:39677 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5348 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10714 ms total)

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