[==========] 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:20:00.703529 23821 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.67.126:36795
I20260812 06:20:00.704463 23821 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:20:00.704988 23821 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:00.711018 23827 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:20:00.711020 23828 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:20:00.711241 23821 server_base.cc:1061] running on GCE node
W20260812 06:20:00.711436 23831 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:20:00.711863 23821 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:00.712028 23821 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:20:00.712088 23821 hybrid_clock.cc:648] HybridClock initialized: now 1786515600712085 us; error 0 us; skew 500 ppm
I20260812 06:20:00.713781 23821 webserver.cc:533] Webserver started at http://127.23.67.126:40253/ using document root <none> and password file <none>
I20260812 06:20:00.714326 23821 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:00.714414 23821 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:00.714663 23821 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:00.716331 23821 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/master-0-root/instance:
uuid: "0b63319fe84447afa1c2eec84cf08c71"
format_stamp: "Formatted at 2026-08-12 06:20:00 on dist-test-slave-vkjp"
I20260812 06:20:00.719651 23821 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:00.721624 23837 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:20:00.722599 23821 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:00.722728 23821 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/master-0-root
uuid: "0b63319fe84447afa1c2eec84cf08c71"
format_stamp: "Formatted at 2026-08-12 06:20:00 on dist-test-slave-vkjp"
I20260812 06:20:00.722829 23821 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-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:20:00.741094 23821 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:00.741734 23821 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:20:00.741914 23821 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:00.749576 23821 rpc_server.cc:307] RPC server started. Bound to: 127.23.67.126:36795
I20260812 06:20:00.749583 23905 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.67.126:36795 every 8 connection(s)
I20260812 06:20:00.752031 23906 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:20:00.758324 23906 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71: Bootstrap starting.
I20260812 06:20:00.760852 23906 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:00.762360 23906 log.cc:826] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:00.764213 23906 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71: No bootstrap required, opened a new log
I20260812 06:20:00.767069 23906 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b63319fe84447afa1c2eec84cf08c71" member_type: VOTER }
I20260812 06:20:00.767354 23906 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:00.767462 23906 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0b63319fe84447afa1c2eec84cf08c71, State: Initialized, Role: FOLLOWER
I20260812 06:20:00.768095 23906 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [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: "0b63319fe84447afa1c2eec84cf08c71" member_type: VOTER }
I20260812 06:20:00.768280 23906 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:00.768379 23906 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:00.768518 23906 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:00.769385 23906 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b63319fe84447afa1c2eec84cf08c71" member_type: VOTER }
I20260812 06:20:00.769860 23906 leader_election.cc:304] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [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: 0b63319fe84447afa1c2eec84cf08c71; no voters: 
I20260812 06:20:00.770206 23906 leader_election.cc:290] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:00.770344 23909 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:00.770612 23909 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 1 LEADER]: Becoming Leader. State: Replica: 0b63319fe84447afa1c2eec84cf08c71, State: Running, Role: LEADER
I20260812 06:20:00.771064 23909 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [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: "0b63319fe84447afa1c2eec84cf08c71" member_type: VOTER }
I20260812 06:20:00.771418 23906 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:00.773031 23910 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0b63319fe84447afa1c2eec84cf08c71" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b63319fe84447afa1c2eec84cf08c71" member_type: VOTER } }
I20260812 06:20:00.773016 23911 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0b63319fe84447afa1c2eec84cf08c71. Latest consensus state: current_term: 1 leader_uuid: "0b63319fe84447afa1c2eec84cf08c71" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b63319fe84447afa1c2eec84cf08c71" member_type: VOTER } }
I20260812 06:20:00.773160 23911 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:00.773160 23910 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:00.773612 23922 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:00.773958 23821 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:00.775986 23922 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:00.780431 23922 catalog_manager.cc:1383] Generated new cluster ID: 16d950510ab348298b1b9a99a568c623
I20260812 06:20:00.780493 23922 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:00.792179 23922 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:00.793058 23922 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:00.800493 23922 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71: Generated new TSK 0
I20260812 06:20:00.801106 23922 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:00.806643 23821 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:00.809206 23932 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:20:00.809296 23935 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:20:00.809506 23933 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:20:00.809679 23821 server_base.cc:1061] running on GCE node
I20260812 06:20:00.809895 23821 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:00.809966 23821 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:20:00.809993 23821 hybrid_clock.cc:648] HybridClock initialized: now 1786515600809991 us; error 0 us; skew 500 ppm
I20260812 06:20:00.810936 23821 webserver.cc:533] Webserver started at http://127.23.67.65:33091/ using document root <none> and password file <none>
I20260812 06:20:00.811137 23821 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:00.811199 23821 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:00.811275 23821 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:00.811636 23821 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/instance:
uuid: "825fa5c10adf41e5b38112be7fe6d87f"
format_stamp: "Formatted at 2026-08-12 06:20:00 on dist-test-slave-vkjp"
I20260812 06:20:00.813097 23821 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:00.814085 23941 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:20:00.814322 23821 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:00.814410 23821 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root
uuid: "825fa5c10adf41e5b38112be7fe6d87f"
format_stamp: "Formatted at 2026-08-12 06:20:00 on dist-test-slave-vkjp"
I20260812 06:20:00.814496 23821 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-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:20:00.824111 23821 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:00.824565 23821 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:00.825080 23821 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:00.825881 23821 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:00.825964 23821 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:00.826040 23821 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:00.826083 23821 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:00.832708 23821 rpc_server.cc:307] RPC server started. Bound to: 127.23.67.65:43201
I20260812 06:20:00.832767 24022 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.67.65:43201 every 8 connection(s)
I20260812 06:20:00.842770 24023 heartbeater.cc:344] Connected to a master server at 127.23.67.126:36795
I20260812 06:20:00.843026 24023 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:00.843530 24023 heartbeater.cc:507] Master 127.23.67.126:36795 requested a full tablet report, sending...
I20260812 06:20:00.844928 23860 ts_manager.cc:194] Registered new tserver with Master: 825fa5c10adf41e5b38112be7fe6d87f (127.23.67.65:43201)
I20260812 06:20:00.845737 23821 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012363018s
I20260812 06:20:00.846331 23860 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53512
I20260812 06:20:00.855414 23860 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53528:
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:20:00.869737 23978 tablet_service.cc:1511] Processing CreateTablet for tablet 75a0f549cf624af2a8b2dbf326bee489 (DEFAULT_TABLE table=heavy-update-compaction-test [id=18e049b356a74a68bf3e962a588329a6]), partition=
I20260812 06:20:00.870251 23978 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 75a0f549cf624af2a8b2dbf326bee489. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:00.875403 24039 tablet_bootstrap.cc:492] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Bootstrap starting.
I20260812 06:20:00.876559 24039 tablet_bootstrap.cc:654] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:00.877936 24039 tablet_bootstrap.cc:492] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: No bootstrap required, opened a new log
I20260812 06:20:00.878046 24039 ts_tablet_manager.cc:1403] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:00.878543 24039 raft_consensus.cc:359] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "825fa5c10adf41e5b38112be7fe6d87f" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 43201 } }
I20260812 06:20:00.878687 24039 raft_consensus.cc:385] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:00.878724 24039 raft_consensus.cc:740] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 825fa5c10adf41e5b38112be7fe6d87f, State: Initialized, Role: FOLLOWER
I20260812 06:20:00.878857 24039 consensus_queue.cc:260] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [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: "825fa5c10adf41e5b38112be7fe6d87f" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 43201 } }
I20260812 06:20:00.878966 24039 raft_consensus.cc:399] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:00.879002 24039 raft_consensus.cc:493] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:00.879051 24039 raft_consensus.cc:3060] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:00.880059 24039 raft_consensus.cc:515] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "825fa5c10adf41e5b38112be7fe6d87f" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 43201 } }
I20260812 06:20:00.880204 24039 leader_election.cc:304] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [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: 825fa5c10adf41e5b38112be7fe6d87f; no voters: 
I20260812 06:20:00.880410 24039 leader_election.cc:290] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:00.880599 24042 raft_consensus.cc:2804] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:00.880719 24039 ts_tablet_manager.cc:1434] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:20:00.880888 24042 raft_consensus.cc:697] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 1 LEADER]: Becoming Leader. State: Replica: 825fa5c10adf41e5b38112be7fe6d87f, State: Running, Role: LEADER
I20260812 06:20:00.881201 24023 heartbeater.cc:499] Master 127.23.67.126:36795 was elected leader, sending a full tablet report...
I20260812 06:20:00.881469 24042 consensus_queue.cc:237] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [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: "825fa5c10adf41e5b38112be7fe6d87f" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 43201 } }
I20260812 06:20:00.884356 23860 catalog_manager.cc:5719] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f reported cstate change: term changed from 0 to 1, leader changed from <none> to 825fa5c10adf41e5b38112be7fe6d87f (127.23.67.65). New cstate: current_term: 1 leader_uuid: "825fa5c10adf41e5b38112be7fe6d87f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "825fa5c10adf41e5b38112be7fe6d87f" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 43201 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:00.951699 23821 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.022s	sys 0.008s
I20260812 06:20:01.083761 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489): perf score=19.054940
I20260812 06:20:01.267699 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.184s	user 0.152s	sys 0.029s Metrics: {"bytes_written":13415136,"cfile_init":1,"compiler_manager_pool.queue_time_us":188,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1005,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45737,"lbm_writes_lt_1ms":784,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":141696,"thread_start_us":105,"threads_started":1,"update_count":1635}
I20260812 06:20:01.268853 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling LogGCOp(75a0f549cf624af2a8b2dbf326bee489): free 20743880 bytes of WAL
I20260812 06:20:01.269176 23948 log_reader.cc:385] T 75a0f549cf624af2a8b2dbf326bee489: removed 2 log segments from log reader
I20260812 06:20:01.269258 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000001 (ops 1-6)
I20260812 06:20:01.269325 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000002 (ops 7-11)
I20260812 06:20:01.274587 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: LogGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:01.275116 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:01.298130 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.023s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4184711,"delete_count":0,"lbm_write_time_us":6133,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:20:01.298614 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.196750
I20260812 06:20:01.309711 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:20:01.310225 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:01.480844 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.170s	user 0.110s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774777,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":530,"lbm_read_time_us":12603,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27917,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":319,"threads_started":5,"update_count":2500}
I20260812 06:20:01.481482 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:01.516665 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15227,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.517081 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489): 16411393 bytes on disk
I20260812 06:20:01.517508 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.517866 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:01.532373 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.532828 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:01.657169 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.123s	user 0.085s	sys 0.037s 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":398,"lbm_read_time_us":7207,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25377,"lbm_writes_lt_1ms":443,"mutex_wait_us":127,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.657788 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:01.703701 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.046s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":15125,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.704208 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:01.715564 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.716301 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:01.849371 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.133s	user 0.088s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672282,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":9224,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26512,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.850097 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:01.895392 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.045s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16202,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.895949 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:01.912088 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.912706 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.052034 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.139s	user 0.120s	sys 0.016s 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":10832,"lbm_read_time_us":8372,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28567,"lbm_writes_lt_1ms":443,"mutex_wait_us":3490,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2000}
I20260812 06:20:02.052630 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:02.098048 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.045s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16428,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.098785 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:02.109728 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.110172 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.256243 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.146s	user 0.114s	sys 0.031s 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":942,"lbm_read_time_us":10729,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23023,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:20:02.256836 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:02.297632 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17849,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.298147 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:02.314401 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.315220 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.437598 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.122s	user 0.089s	sys 0.033s 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":559,"lbm_read_time_us":9786,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22082,"lbm_writes_lt_1ms":443,"mutex_wait_us":93,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:20:02.438297 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:02.478866 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.040s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19003,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.479410 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:02.492468 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.492918 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.523722 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1496,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1511,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:02.524529 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling LogGCOp(75a0f549cf624af2a8b2dbf326bee489): free 112239272 bytes of WAL
I20260812 06:20:02.524778 23948 log_reader.cc:385] T 75a0f549cf624af2a8b2dbf326bee489: removed 11 log segments from log reader
I20260812 06:20:02.524823 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000003 (ops 12-16)
I20260812 06:20:02.524853 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000004 (ops 17-21)
I20260812 06:20:02.524914 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000005 (ops 22-26)
I20260812 06:20:02.524962 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000006 (ops 27-31)
I20260812 06:20:02.525022 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000007 (ops 32-36)
I20260812 06:20:02.525050 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000008 (ops 37-40)
I20260812 06:20:02.525106 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000009 (ops 41-45)
I20260812 06:20:02.525131 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000010 (ops 46-50)
I20260812 06:20:02.525168 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000011 (ops 51-55)
I20260812 06:20:02.525208 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000012 (ops 56-60)
I20260812 06:20:02.525242 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000013 (ops 61-65)
I20260812 06:20:02.549240 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: LogGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:02.549664 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=4.173312
I20260812 06:20:02.564755 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":6194893,"delete_count":0,"lbm_write_time_us":6256,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:20:02.565240 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling LogGCOp(75a0f549cf624af2a8b2dbf326bee489): free 12017983 bytes of WAL
I20260812 06:20:02.565464 23948 log_reader.cc:385] T 75a0f549cf624af2a8b2dbf326bee489: removed 1 log segments from log reader
I20260812 06:20:02.565506 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000014 (ops 66-70)
I20260812 06:20:02.568423 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: LogGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:02.568928 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.579774 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":3126,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:20:02.580344 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.751597 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.171s	user 0.136s	sys 0.034s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877287,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":301,"lbm_read_time_us":10228,"lbm_reads_lt_1ms":670,"lbm_write_time_us":35982,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:20:02.752349 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489): 462 bytes on disk
I20260812 06:20:02.752758 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.753254 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:02.802639 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.049s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22021,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.803304 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:02.815062 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4543,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.815680 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:02.969005 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.153s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":720,"lbm_read_time_us":9309,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29541,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:02.969780 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:03.027778 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.058s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23136,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.028384 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:03.039677 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.040151 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:03.184198 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.144s	user 0.104s	sys 0.040s 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":164,"lbm_read_time_us":9843,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28979,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:03.184958 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=11.118625
I20260812 06:20:03.218773 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.034s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14730,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:03.219384 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:03.232192 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4405,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.232705 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:03.361143 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":7719,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25876,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:20:03.361806 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:03.415558 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.053s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.416145 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:03.426741 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.427305 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:03.591702 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.164s	user 0.097s	sys 0.061s 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":372,"lbm_read_time_us":10048,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26083,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.592630 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:03.628328 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.035s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13451,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.629031 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:03.728196 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.099s	user 0.083s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":448,"lbm_read_time_us":5712,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18350,"lbm_writes_lt_1ms":343,"mutex_wait_us":83,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":1500}
I20260812 06:20:03.729144 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:03.764485 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.035s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15291,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.764961 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:03.776153 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.776788 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:03.900810 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.124s	user 0.097s	sys 0.026s 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":741,"lbm_read_time_us":7903,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22787,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:20:03.901698 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=10.126437
I20260812 06:20:03.944569 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.043s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15526,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.945078 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:03.956151 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.956704 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:03.997115 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.040s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1339,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1686,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:03.997836 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling LogGCOp(75a0f549cf624af2a8b2dbf326bee489): free 120553390 bytes of WAL
I20260812 06:20:03.998127 23948 log_reader.cc:385] T 75a0f549cf624af2a8b2dbf326bee489: removed 12 log segments from log reader
I20260812 06:20:03.998190 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000015 (ops 71-75)
I20260812 06:20:03.998229 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000016 (ops 76-80)
I20260812 06:20:03.998256 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000017 (ops 81-84)
I20260812 06:20:03.998281 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000018 (ops 85-89)
I20260812 06:20:03.998303 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000019 (ops 90-94)
I20260812 06:20:03.998325 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000020 (ops 95-99)
I20260812 06:20:03.998347 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000021 (ops 100-104)
I20260812 06:20:03.998386 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000022 (ops 105-109)
I20260812 06:20:03.998423 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000023 (ops 110-114)
I20260812 06:20:03.998452 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000024 (ops 115-119)
I20260812 06:20:03.998481 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000025 (ops 120-124)
I20260812 06:20:03.998503 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000026 (ops 125-128)
I20260812 06:20:04.028808 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: LogGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:04.029241 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489): 483 bytes on disk
I20260812 06:20:04.030063 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.030616 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=3.181125
I20260812 06:20:04.055441 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.025s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5829,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.055887 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:04.065181 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3492,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.065616 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:04.249894 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.184s	user 0.126s	sys 0.057s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":379,"lbm_read_time_us":12390,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30683,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:20:04.250605 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:04.299288 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.048s	user 0.041s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19440,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.299798 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:04.445117 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.145s	user 0.098s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":161,"lbm_read_time_us":8453,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22345,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:04.445760 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:04.496093 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.050s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18047,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.496627 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:04.509596 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.510073 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:04.688105 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.178s	user 0.122s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":11819,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29304,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:20:04.688925 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:04.740832 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.052s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.741410 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:04.765110 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.024s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5701,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.765671 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:04.915354 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.149s	user 0.113s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1443,"lbm_read_time_us":9314,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27537,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:04.915970 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:04.969411 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.053s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24046,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.969977 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:04.987367 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.017s	user 0.000s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.987906 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:05.132714 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.145s	user 0.104s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":620,"lbm_read_time_us":9651,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29492,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:20:05.133347 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:05.185151 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.052s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22323,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.185782 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:05.197371 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.197880 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:05.350167 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.152s	user 0.108s	sys 0.043s 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":394,"lbm_read_time_us":12258,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31666,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:20:05.350793 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=11.118625
I20260812 06:20:05.383829 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.033s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14522,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.384583 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=2.188937
I20260812 06:20:05.400928 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5815,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.401525 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:05.435741 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushMRSOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.034s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1387,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1623,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:05.436398 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling LogGCOp(75a0f549cf624af2a8b2dbf326bee489): free 124710562 bytes of WAL
I20260812 06:20:05.436622 23948 log_reader.cc:385] T 75a0f549cf624af2a8b2dbf326bee489: removed 12 log segments from log reader
I20260812 06:20:05.436666 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000027 (ops 129-133)
I20260812 06:20:05.436694 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000028 (ops 134-138)
I20260812 06:20:05.436748 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000029 (ops 139-143)
I20260812 06:20:05.436796 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000030 (ops 144-148)
I20260812 06:20:05.436831 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000031 (ops 149-153)
I20260812 06:20:05.436872 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000032 (ops 154-158)
I20260812 06:20:05.436899 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000033 (ops 159-163)
I20260812 06:20:05.436954 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000034 (ops 164-168)
I20260812 06:20:05.436995 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000035 (ops 169-173)
I20260812 06:20:05.437034 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000036 (ops 174-178)
I20260812 06:20:05.437075 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000037 (ops 179-183)
I20260812 06:20:05.437114 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000038 (ops 184-188)
I20260812 06:20:05.468200 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: LogGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:05.468768 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489): 482 bytes on disk
I20260812 06:20:05.469437 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: UndoDeltaBlockGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.470186 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=3.181125
I20260812 06:20:05.485893 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":6257,"lbm_writes_lt_1ms":131,"mutex_wait_us":63,"reinsert_count":0,"update_count":640}
I20260812 06:20:05.486442 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling LogGCOp(75a0f549cf624af2a8b2dbf326bee489): free 8767138 bytes of WAL
I20260812 06:20:05.486686 23948 log_reader.cc:385] T 75a0f549cf624af2a8b2dbf326bee489: removed 1 log segments from log reader
I20260812 06:20:05.486747 23948 log.cc:1079] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/75a0f549cf624af2a8b2dbf326bee489/wal-000000039 (ops 189-193)
I20260812 06:20:05.488983 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: LogGCOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:05.489318 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.196750
I20260812 06:20:05.502282 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:05.502790 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489): perf score=1.000000
I20260812 06:20:05.671952 23821 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.720s	user 1.812s	sys 0.105s
I20260812 06:20:05.674614 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: MajorDeltaCompactionOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.172s	user 0.138s	sys 0.029s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877302,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":199,"lbm_read_time_us":13106,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32333,"lbm_writes_lt_1ms":643,"mutex_wait_us":66,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:20:05.675351 24024 maintenance_manager.cc:419] P 825fa5c10adf41e5b38112be7fe6d87f: Scheduling FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489): perf score=14.095187
I20260812 06:20:05.702499 23821 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.001s	sys 0.000s
I20260812 06:20:05.703950 23821 tablet_server.cc:179] TabletServer@127.23.67.65:0 shutting down...
I20260812 06:20:05.716074 23948 maintenance_manager.cc:643] P 825fa5c10adf41e5b38112be7fe6d87f: FlushDeltaMemStoresOp(75a0f549cf624af2a8b2dbf326bee489) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17988,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.716769 23821 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:05.717175 23821 tablet_replica.cc:333] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f: stopping tablet replica
I20260812 06:20:05.717376 23821 raft_consensus.cc:2243] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.717568 23821 raft_consensus.cc:2272] T 75a0f549cf624af2a8b2dbf326bee489 P 825fa5c10adf41e5b38112be7fe6d87f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.732558 23821 tablet_server.cc:196] TabletServer@127.23.67.65:0 shutdown complete.
I20260812 06:20:05.737488 23821 master.cc:562] Master@127.23.67.126:36795 shutting down...
I20260812 06:20:05.740994 23821 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.741178 23821 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.741233 23821 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0b63319fe84447afa1c2eec84cf08c71: stopping tablet replica
I20260812 06:20:05.753672 23821 master.cc:584] Master@127.23.67.126:36795 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5136 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:05.839010 23821 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.67.126:35763
I20260812 06:20:05.839444 23821 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:05.841639 24067 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:20:05.841782 24063 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:20:05.841645 24065 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:20:05.842082 23821 server_base.cc:1061] running on GCE node
I20260812 06:20:05.842222 23821 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:05.842254 23821 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:20:05.842269 23821 hybrid_clock.cc:648] HybridClock initialized: now 1786515605842269 us; error 0 us; skew 500 ppm
I20260812 06:20:05.843216 23821 webserver.cc:533] Webserver started at http://127.23.67.126:34453/ using document root <none> and password file <none>
I20260812 06:20:05.843364 23821 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:05.843407 23821 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:05.843467 23821 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:05.843815 23821 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/master-0-root/instance:
uuid: "491be73e9af54038ad76489447e03f66"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-vkjp"
I20260812 06:20:05.845407 23821 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:05.846562 24074 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:20:05.846875 23821 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:05.846958 23821 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/master-0-root
uuid: "491be73e9af54038ad76489447e03f66"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-vkjp"
I20260812 06:20:05.847016 23821 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-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:20:05.860849 23821 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:05.861270 23821 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:05.865265 23821 rpc_server.cc:307] RPC server started. Bound to: 127.23.67.126:35763
I20260812 06:20:05.871644 24141 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.67.126:35763 every 8 connection(s)
I20260812 06:20:05.872581 24142 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:20:05.883332 24142 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66: Bootstrap starting.
I20260812 06:20:05.884200 24142 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:05.885365 24142 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66: No bootstrap required, opened a new log
I20260812 06:20:05.885752 24142 raft_consensus.cc:359] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "491be73e9af54038ad76489447e03f66" member_type: VOTER }
I20260812 06:20:05.885844 24142 raft_consensus.cc:385] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:05.885867 24142 raft_consensus.cc:740] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 491be73e9af54038ad76489447e03f66, State: Initialized, Role: FOLLOWER
I20260812 06:20:05.886025 24142 consensus_queue.cc:260] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [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: "491be73e9af54038ad76489447e03f66" member_type: VOTER }
I20260812 06:20:05.886119 24142 raft_consensus.cc:399] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:05.886144 24142 raft_consensus.cc:493] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:05.886180 24142 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:05.886904 24142 raft_consensus.cc:515] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "491be73e9af54038ad76489447e03f66" member_type: VOTER }
I20260812 06:20:05.887022 24142 leader_election.cc:304] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [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: 491be73e9af54038ad76489447e03f66; no voters: 
I20260812 06:20:05.887264 24142 leader_election.cc:290] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:05.887424 24145 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:05.887658 24145 raft_consensus.cc:697] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 1 LEADER]: Becoming Leader. State: Replica: 491be73e9af54038ad76489447e03f66, State: Running, Role: LEADER
I20260812 06:20:05.887804 24145 consensus_queue.cc:237] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [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: "491be73e9af54038ad76489447e03f66" member_type: VOTER }
I20260812 06:20:05.887840 24142 sys_catalog.cc:565] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:05.888245 24146 sys_catalog.cc:455] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "491be73e9af54038ad76489447e03f66" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "491be73e9af54038ad76489447e03f66" member_type: VOTER } }
I20260812 06:20:05.888360 24146 sys_catalog.cc:458] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:05.888260 24147 sys_catalog.cc:455] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 491be73e9af54038ad76489447e03f66. Latest consensus state: current_term: 1 leader_uuid: "491be73e9af54038ad76489447e03f66" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "491be73e9af54038ad76489447e03f66" member_type: VOTER } }
I20260812 06:20:05.888518 24147 sys_catalog.cc:458] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:05.889128 24149 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:05.889809 24149 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:05.890033 23821 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:05.891808 24149 catalog_manager.cc:1383] Generated new cluster ID: 00bec2d8fbff4581853a317001ab84f8
I20260812 06:20:05.891868 24149 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:05.901235 24149 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:05.901794 24149 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:05.912364 24149 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66: Generated new TSK 0
I20260812 06:20:05.912585 24149 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:05.922693 23821 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:05.924811 24167 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:20:05.924880 24168 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:20:05.924850 23821 server_base.cc:1061] running on GCE node
W20260812 06:20:05.924970 24170 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:20:05.925241 23821 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:05.925287 23821 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:20:05.925304 23821 hybrid_clock.cc:648] HybridClock initialized: now 1786515605925304 us; error 0 us; skew 500 ppm
I20260812 06:20:05.926323 23821 webserver.cc:533] Webserver started at http://127.23.67.65:39741/ using document root <none> and password file <none>
I20260812 06:20:05.926553 23821 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:05.926631 23821 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:05.926729 23821 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:05.927240 23821 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/instance:
uuid: "050c076ccafa4560a4ff7933bc145259"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-vkjp"
I20260812 06:20:05.928927 23821 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:05.930058 24177 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:20:05.930367 23821 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:05.930469 23821 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root
uuid: "050c076ccafa4560a4ff7933bc145259"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-vkjp"
I20260812 06:20:05.930562 23821 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-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:20:05.940378 23821 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:05.940841 23821 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:05.941196 23821 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:05.941711 23821 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:05.941768 23821 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:05.941830 23821 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:05.941879 23821 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:05.946611 23821 rpc_server.cc:307] RPC server started. Bound to: 127.23.67.65:36563
I20260812 06:20:05.946645 24253 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.67.65:36563 every 8 connection(s)
I20260812 06:20:05.956349 24254 heartbeater.cc:344] Connected to a master server at 127.23.67.126:35763
I20260812 06:20:05.956491 24254 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:05.956717 24254 heartbeater.cc:507] Master 127.23.67.126:35763 requested a full tablet report, sending...
I20260812 06:20:05.957422 24095 ts_manager.cc:194] Registered new tserver with Master: 050c076ccafa4560a4ff7933bc145259 (127.23.67.65:36563)
I20260812 06:20:05.958150 24095 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37444
I20260812 06:20:05.958204 23821 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011122528s
I20260812 06:20:05.965767 24095 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37448:
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:20:05.974740 24209 tablet_service.cc:1511] Processing CreateTablet for tablet 8cf3363822554fc6bf8c360553f8ac9b (DEFAULT_TABLE table=heavy-update-compaction-test [id=bf54b3b780a7418c94025353a67dfb18]), partition=
I20260812 06:20:05.975149 24209 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8cf3363822554fc6bf8c360553f8ac9b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:05.977501 24271 tablet_bootstrap.cc:492] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Bootstrap starting.
I20260812 06:20:05.978395 24271 tablet_bootstrap.cc:654] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:05.979707 24271 tablet_bootstrap.cc:492] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: No bootstrap required, opened a new log
I20260812 06:20:05.979826 24271 ts_tablet_manager.cc:1403] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:05.980397 24271 raft_consensus.cc:359] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "050c076ccafa4560a4ff7933bc145259" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 36563 } }
I20260812 06:20:05.980561 24271 raft_consensus.cc:385] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:05.980613 24271 raft_consensus.cc:740] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 050c076ccafa4560a4ff7933bc145259, State: Initialized, Role: FOLLOWER
I20260812 06:20:05.980772 24271 consensus_queue.cc:260] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [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: "050c076ccafa4560a4ff7933bc145259" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 36563 } }
I20260812 06:20:05.980866 24271 raft_consensus.cc:399] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:05.980911 24271 raft_consensus.cc:493] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:05.980962 24271 raft_consensus.cc:3060] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:05.981748 24271 raft_consensus.cc:515] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "050c076ccafa4560a4ff7933bc145259" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 36563 } }
I20260812 06:20:05.981912 24271 leader_election.cc:304] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [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: 050c076ccafa4560a4ff7933bc145259; no voters: 
I20260812 06:20:05.982148 24271 leader_election.cc:290] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:05.982313 24273 raft_consensus.cc:2804] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:05.982576 24271 ts_tablet_manager.cc:1434] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:05.982561 24273 raft_consensus.cc:697] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 1 LEADER]: Becoming Leader. State: Replica: 050c076ccafa4560a4ff7933bc145259, State: Running, Role: LEADER
I20260812 06:20:05.982558 24254 heartbeater.cc:499] Master 127.23.67.126:35763 was elected leader, sending a full tablet report...
I20260812 06:20:05.982982 24273 consensus_queue.cc:237] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [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: "050c076ccafa4560a4ff7933bc145259" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 36563 } }
I20260812 06:20:05.984477 24095 catalog_manager.cc:5719] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 reported cstate change: term changed from 0 to 1, leader changed from <none> to 050c076ccafa4560a4ff7933bc145259 (127.23.67.65). New cstate: current_term: 1 leader_uuid: "050c076ccafa4560a4ff7933bc145259" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "050c076ccafa4560a4ff7933bc145259" member_type: VOTER last_known_addr { host: "127.23.67.65" port: 36563 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:06.044572 23821 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.020s	sys 0.004s
I20260812 06:20:06.197634 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=19.054940
I20260812 06:20:06.336030 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.138s	user 0.105s	sys 0.032s Metrics: {"bytes_written":12307493,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":857,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35047,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:20:06.336825 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling LogGCOp(8cf3363822554fc6bf8c360553f8ac9b): free 20290830 bytes of WAL
I20260812 06:20:06.337144 24182 log_reader.cc:385] T 8cf3363822554fc6bf8c360553f8ac9b: removed 2 log segments from log reader
I20260812 06:20:06.337209 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000001 (ops 1-6)
I20260812 06:20:06.337266 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000002 (ops 7-10)
I20260812 06:20:06.342056 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: LogGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:06.342554 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b): 16411393 bytes on disk
I20260812 06:20:06.343104 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:20:06.343544 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:06.367075 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.023s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.367532 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:06.377556 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.378013 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:06.555299 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.177s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774810,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":485,"lbm_read_time_us":12522,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27197,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":335,"threads_started":5,"update_count":2500}
I20260812 06:20:06.555780 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=14.095187
I20260812 06:20:06.615197 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.059s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22270,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.615608 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:06.625962 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.626719 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:06.778435 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.151s	user 0.121s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":8685,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30052,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2500}
I20260812 06:20:06.779263 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=13.103000
I20260812 06:20:06.827783 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.048s	user 0.027s	sys 0.020s Metrics: {"bytes_written":15466352,"delete_count":0,"lbm_write_time_us":21849,"lbm_writes_lt_1ms":380,"reinsert_count":0,"update_count":1885}
I20260812 06:20:06.828539 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:06.979923 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.151s	user 0.127s	sys 0.024s Metrics: {"cfile_cache_miss":408,"cfile_cache_miss_bytes":19728608,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":215,"lbm_read_time_us":9953,"lbm_reads_lt_1ms":440,"lbm_write_time_us":24225,"lbm_writes_lt_1ms":420,"mutex_wait_us":43,"peak_mem_usage":47664755,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":1885}
I20260812 06:20:06.980610 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=11.118625
I20260812 06:20:07.016991 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.036s	user 0.015s	sys 0.020s Metrics: {"bytes_written":13251048,"delete_count":0,"lbm_write_time_us":15159,"lbm_writes_lt_1ms":326,"reinsert_count":0,"update_count":1615}
I20260812 06:20:07.017652 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:07.039745 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.022s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.040294 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:07.054525 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.054992 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:07.245963 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.191s	user 0.136s	sys 0.053s Metrics: {"cfile_cache_miss":556,"cfile_cache_miss_bytes":25718366,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":73,"lbm_read_time_us":10561,"lbm_reads_lt_1ms":596,"lbm_write_time_us":30916,"lbm_writes_lt_1ms":566,"mutex_wait_us":20,"peak_mem_usage":65100089,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2615}
I20260812 06:20:07.246595 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=14.095187
I20260812 06:20:07.297513 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.048s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":20650,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:07.298050 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:07.322383 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5035,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:07.322840 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:07.342757 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.020s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.343341 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:07.555437 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.212s	user 0.147s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":62,"lbm_read_time_us":14153,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33220,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":3000}
I20260812 06:20:07.556075 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=18.063937
I20260812 06:20:07.621500 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.065s	user 0.043s	sys 0.019s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25097,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:07.622069 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:07.633076 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.633564 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:07.664052 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1377,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1709,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:07.664659 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling LogGCOp(8cf3363822554fc6bf8c360553f8ac9b): free 121006380 bytes of WAL
I20260812 06:20:07.664911 24182 log_reader.cc:385] T 8cf3363822554fc6bf8c360553f8ac9b: removed 12 log segments from log reader
I20260812 06:20:07.664968 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000003 (ops 11-15)
I20260812 06:20:07.665009 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000004 (ops 16-20)
I20260812 06:20:07.665041 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000005 (ops 21-25)
I20260812 06:20:07.665064 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000006 (ops 26-30)
I20260812 06:20:07.665086 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000007 (ops 31-35)
I20260812 06:20:07.665125 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000008 (ops 36-40)
I20260812 06:20:07.665158 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000009 (ops 41-45)
I20260812 06:20:07.665192 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000010 (ops 46-50)
I20260812 06:20:07.665221 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000011 (ops 51-55)
I20260812 06:20:07.665247 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000012 (ops 56-60)
I20260812 06:20:07.665277 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000013 (ops 61-64)
I20260812 06:20:07.665303 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000014 (ops 65-69)
I20260812 06:20:07.691716 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: LogGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:07.692109 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b): 482 bytes on disk
I20260812 06:20:07.692510 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b) 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:20:07.692935 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:07.711503 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.711905 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:07.936257 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.224s	user 0.145s	sys 0.076s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":775,"lbm_read_time_us":13964,"lbm_reads_lt_1ms":765,"lbm_write_time_us":39039,"lbm_writes_lt_1ms":743,"mutex_wait_us":369,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21760,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:20:07.937124 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=18.063937
I20260812 06:20:08.008708 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.071s	user 0.041s	sys 0.028s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":32906,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:20:08.009292 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:08.030777 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.021s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.031299 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:08.040871 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.041277 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:08.256665 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.215s	user 0.166s	sys 0.048s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979636,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":841,"lbm_read_time_us":14513,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42392,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3500}
I20260812 06:20:08.257359 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=15.087375
I20260812 06:20:08.304821 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.047s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16820147,"delete_count":0,"lbm_write_time_us":20636,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:08.306509 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:08.331244 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:08.331724 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:08.341709 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.342160 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:08.510991 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.169s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":772,"lbm_read_time_us":11603,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32719,"lbm_writes_lt_1ms":643,"mutex_wait_us":273,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":3000}
I20260812 06:20:08.511771 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=14.095187
I20260812 06:20:08.554502 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.043s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19114,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.555006 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:08.567056 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.567710 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:08.727447 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.160s	user 0.123s	sys 0.031s 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":801,"lbm_read_time_us":12664,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28808,"lbm_writes_lt_1ms":543,"mutex_wait_us":317,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:20:08.729171 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=12.110812
I20260812 06:20:08.768929 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":13579242,"delete_count":0,"lbm_write_time_us":18177,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:20:08.769389 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.196750
I20260812 06:20:08.778271 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.009s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2802,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:20:08.778959 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:08.922652 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.143s	user 0.096s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672250,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":9391,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23799,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:20:08.923425 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=11.118625
I20260812 06:20:08.956565 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.033s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14224,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:08.957115 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:08.984025 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.027s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4864,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:08.984515 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:09.005497 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.021s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.006204 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:09.047870 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.041s	user 0.036s	sys 0.003s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1414,"drs_written":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2247,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:09.048669 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling LogGCOp(8cf3363822554fc6bf8c360553f8ac9b): free 120100387 bytes of WAL
I20260812 06:20:09.048956 24182 log_reader.cc:385] T 8cf3363822554fc6bf8c360553f8ac9b: removed 12 log segments from log reader
I20260812 06:20:09.049028 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000015 (ops 70-74)
I20260812 06:20:09.049084 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000016 (ops 75-78)
I20260812 06:20:09.049117 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000017 (ops 79-83)
I20260812 06:20:09.049153 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000018 (ops 84-88)
I20260812 06:20:09.049190 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000019 (ops 89-93)
I20260812 06:20:09.049229 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000020 (ops 94-98)
I20260812 06:20:09.049268 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000021 (ops 99-102)
I20260812 06:20:09.049306 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000022 (ops 103-107)
I20260812 06:20:09.049345 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000023 (ops 108-112)
I20260812 06:20:09.049382 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000024 (ops 113-117)
I20260812 06:20:09.049438 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000025 (ops 118-122)
I20260812 06:20:09.049474 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000026 (ops 123-126)
I20260812 06:20:09.073889 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: LogGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:09.074498 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:09.093124 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.018s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.093556 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:09.103538 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.103946 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:09.330078 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.226s	user 0.142s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979862,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":665,"lbm_read_time_us":15919,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33820,"lbm_writes_lt_1ms":743,"mutex_wait_us":321,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20096,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:20:09.330830 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b): 447 bytes on disk
I20260812 06:20:09.331467 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":149,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.331998 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=18.063937
I20260812 06:20:09.396772 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.065s	user 0.031s	sys 0.023s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25289,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:09.397203 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:09.407590 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.408056 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:09.603739 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.196s	user 0.124s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1144,"lbm_read_time_us":12554,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33071,"lbm_writes_lt_1ms":643,"mutex_wait_us":473,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:20:09.604401 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=15.087375
I20260812 06:20:09.651978 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.047s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20101,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:09.652590 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:09.675979 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.023s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:09.676482 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:09.691056 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.691606 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:09.887931 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.196s	user 0.143s	sys 0.053s 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":124,"lbm_read_time_us":11919,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33291,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":3000}
I20260812 06:20:09.888619 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=14.095187
I20260812 06:20:09.937381 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.049s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20090,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.938031 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:10.107249 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.169s	user 0.110s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":367,"lbm_read_time_us":11024,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25879,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":605312,"update_count":2000}
I20260812 06:20:10.107959 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=14.095187
I20260812 06:20:10.159740 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.052s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19664,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.160235 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:10.171787 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.172250 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:10.350340 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.178s	user 0.125s	sys 0.050s 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":494,"lbm_read_time_us":10009,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29467,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:20:10.350947 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=14.095187
I20260812 06:20:10.401295 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.050s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23968,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.401883 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:10.418012 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.418597 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:10.467180 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushMRSOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.048s	user 0.032s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1202,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3639,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:10.467905 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b): 462 bytes on disk
I20260812 06:20:10.468386 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: UndoDeltaBlockGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:20:10.468884 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=3.181125
I20260812 06:20:10.486042 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.017s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4413,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:10.486629 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling LogGCOp(8cf3363822554fc6bf8c360553f8ac9b): free 121006632 bytes of WAL
I20260812 06:20:10.486897 24182 log_reader.cc:385] T 8cf3363822554fc6bf8c360553f8ac9b: removed 12 log segments from log reader
I20260812 06:20:10.486970 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000027 (ops 127-131)
I20260812 06:20:10.487023 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000028 (ops 132-136)
I20260812 06:20:10.487076 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000029 (ops 137-141)
I20260812 06:20:10.487145 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000030 (ops 142-146)
I20260812 06:20:10.487185 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000031 (ops 147-151)
I20260812 06:20:10.487226 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000032 (ops 152-156)
I20260812 06:20:10.487263 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000033 (ops 157-161)
I20260812 06:20:10.487303 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000034 (ops 162-166)
I20260812 06:20:10.487340 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000035 (ops 167-170)
I20260812 06:20:10.487378 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000036 (ops 171-175)
I20260812 06:20:10.487417 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000037 (ops 176-180)
I20260812 06:20:10.487449 24182 log.cc:1079] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: Deleting log segment in path: /tmp/dist-test-task4clUIO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515600692909-23821-0/minicluster-data/ts-0-root/wals/8cf3363822554fc6bf8c360553f8ac9b/wal-000000038 (ops 181-185)
I20260812 06:20:10.511471 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: LogGCOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:10.512063 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:10.535521 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.023s	user 0.003s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3912,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:10.536072 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=2.188937
I20260812 06:20:10.546010 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.546697 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=1.000000
I20260812 06:20:10.795360 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: MajorDeltaCompactionOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.248s	user 0.156s	sys 0.088s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":702,"lbm_read_time_us":18434,"lbm_reads_lt_1ms":875,"lbm_write_time_us":42410,"lbm_writes_lt_1ms":843,"mutex_wait_us":46,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":20864,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:20:10.796208 24255 maintenance_manager.cc:419] P 050c076ccafa4560a4ff7933bc145259: Scheduling FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b): perf score=18.063937
I20260812 06:20:10.823439 23821 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.779s	user 1.833s	sys 0.127s
I20260812 06:20:10.851666 23821 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.028s	user 0.004s	sys 0.000s
I20260812 06:20:10.852240 23821 tablet_server.cc:179] TabletServer@127.23.67.65:0 shutting down...
I20260812 06:20:10.857429 24182 maintenance_manager.cc:643] P 050c076ccafa4560a4ff7933bc145259: FlushDeltaMemStoresOp(8cf3363822554fc6bf8c360553f8ac9b) complete. Timing: real 0.061s	user 0.038s	sys 0.019s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27034,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:10.857954 23821 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:10.858168 23821 tablet_replica.cc:333] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259: stopping tablet replica
I20260812 06:20:10.858330 23821 raft_consensus.cc:2243] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:10.858508 23821 raft_consensus.cc:2272] T 8cf3363822554fc6bf8c360553f8ac9b P 050c076ccafa4560a4ff7933bc145259 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:10.873550 23821 tablet_server.cc:196] TabletServer@127.23.67.65:0 shutdown complete.
I20260812 06:20:10.876711 23821 master.cc:562] Master@127.23.67.126:35763 shutting down...
I20260812 06:20:10.880031 23821 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:10.880203 23821 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:10.880252 23821 tablet_replica.cc:333] T 00000000000000000000000000000000 P 491be73e9af54038ad76489447e03f66: stopping tablet replica
I20260812 06:20:10.892490 23821 master.cc:584] Master@127.23.67.126:35763 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5138 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10275 ms total)

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