[==========] 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:16:41.336513 21850 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.86.190:46415
I20260812 06:16:41.337550 21850 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:16:41.338295 21850 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:41.345270 21850 server_base.cc:1061] running on GCE node
W20260812 06:16:41.345194 21859 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:41.345202 21864 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:16:41.345494 21857 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:41.345980 21850 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.346119 21850 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:16:41.346165 21850 hybrid_clock.cc:648] HybridClock initialized: now 1786515401346162 us; error 0 us; skew 500 ppm
I20260812 06:16:41.347972 21850 webserver.cc:533] Webserver started at http://127.21.86.190:42179/ using document root <none> and password file <none>
I20260812 06:16:41.348554 21850 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.348644 21850 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.348876 21850 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.350637 21850 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/master-0-root/instance:
uuid: "81c4eb2bca514682be0209f55e059b82"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-7nm7"
I20260812 06:16:41.354219 21850 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:41.356411 21876 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:16:41.357558 21850 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:41.357717 21850 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/master-0-root
uuid: "81c4eb2bca514682be0209f55e059b82"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-7nm7"
I20260812 06:16:41.357836 21850 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-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:16:41.367030 21850 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.367615 21850 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:16:41.367799 21850 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.375551 21850 rpc_server.cc:307] RPC server started. Bound to: 127.21.86.190:46415
I20260812 06:16:41.375555 21968 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.86.190:46415 every 8 connection(s)
I20260812 06:16:41.377671 21970 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:16:41.383028 21970 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82: Bootstrap starting.
I20260812 06:16:41.385390 21970 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:41.386405 21970 log.cc:826] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:41.388105 21970 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82: No bootstrap required, opened a new log
I20260812 06:16:41.390852 21970 raft_consensus.cc:359] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "81c4eb2bca514682be0209f55e059b82" member_type: VOTER }
I20260812 06:16:41.391010 21970 raft_consensus.cc:385] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:41.391079 21970 raft_consensus.cc:740] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 81c4eb2bca514682be0209f55e059b82, State: Initialized, Role: FOLLOWER
I20260812 06:16:41.391794 21970 consensus_queue.cc:260] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [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: "81c4eb2bca514682be0209f55e059b82" member_type: VOTER }
I20260812 06:16:41.391997 21970 raft_consensus.cc:399] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:41.392068 21970 raft_consensus.cc:493] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:41.392212 21970 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:41.393131 21970 raft_consensus.cc:515] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "81c4eb2bca514682be0209f55e059b82" member_type: VOTER }
I20260812 06:16:41.393548 21970 leader_election.cc:304] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [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: 81c4eb2bca514682be0209f55e059b82; no voters: 
I20260812 06:16:41.393882 21970 leader_election.cc:290] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:41.394022 21975 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:41.394312 21975 raft_consensus.cc:697] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 1 LEADER]: Becoming Leader. State: Replica: 81c4eb2bca514682be0209f55e059b82, State: Running, Role: LEADER
I20260812 06:16:41.394668 21975 consensus_queue.cc:237] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [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: "81c4eb2bca514682be0209f55e059b82" member_type: VOTER }
I20260812 06:16:41.394862 21970 sys_catalog.cc:565] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:41.396536 21976 sys_catalog.cc:455] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "81c4eb2bca514682be0209f55e059b82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "81c4eb2bca514682be0209f55e059b82" member_type: VOTER } }
I20260812 06:16:41.396566 21977 sys_catalog.cc:455] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 81c4eb2bca514682be0209f55e059b82. Latest consensus state: current_term: 1 leader_uuid: "81c4eb2bca514682be0209f55e059b82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "81c4eb2bca514682be0209f55e059b82" member_type: VOTER } }
I20260812 06:16:41.396665 21976 sys_catalog.cc:458] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:41.396664 21977 sys_catalog.cc:458] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:41.397020 21995 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:41.397274 21850 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:41.399277 21995 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:41.403487 21995 catalog_manager.cc:1383] Generated new cluster ID: 25a6082dcd134739a297f97469d62e55
I20260812 06:16:41.403551 21995 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:41.414744 21995 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:41.415756 21995 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:41.421782 21995 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82: Generated new TSK 0
I20260812 06:16:41.422412 21995 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:41.429855 21850 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:41.432770 22014 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:16:41.432842 22020 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:16:41.433018 22018 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:16:41.433139 21850 server_base.cc:1061] running on GCE node
I20260812 06:16:41.433394 21850 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.433439 21850 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:16:41.433454 21850 hybrid_clock.cc:648] HybridClock initialized: now 1786515401433454 us; error 0 us; skew 500 ppm
I20260812 06:16:41.434469 21850 webserver.cc:533] Webserver started at http://127.21.86.129:45829/ using document root <none> and password file <none>
I20260812 06:16:41.434660 21850 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.434717 21850 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.434806 21850 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.435179 21850 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/instance:
uuid: "917cd9dc8438404d84c31ae10ff00064"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-7nm7"
I20260812 06:16:41.436664 21850 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:41.440171 22030 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:16:41.440579 21850 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.000s
I20260812 06:16:41.440660 21850 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root
uuid: "917cd9dc8438404d84c31ae10ff00064"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-7nm7"
I20260812 06:16:41.440752 21850 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-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:16:41.452668 21850 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.453121 21850 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.453646 21850 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:41.454931 21850 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:41.454984 21850 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.455049 21850 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:41.455099 21850 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.461660 21850 rpc_server.cc:307] RPC server started. Bound to: 127.21.86.129:44419
I20260812 06:16:41.461758 22149 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.86.129:44419 every 8 connection(s)
I20260812 06:16:41.471601 22150 heartbeater.cc:344] Connected to a master server at 127.21.86.190:46415
I20260812 06:16:41.471869 22150 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:41.472298 22150 heartbeater.cc:507] Master 127.21.86.190:46415 requested a full tablet report, sending...
I20260812 06:16:41.473627 21908 ts_manager.cc:194] Registered new tserver with Master: 917cd9dc8438404d84c31ae10ff00064 (127.21.86.129:44419)
I20260812 06:16:41.473834 21850 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011481348s
I20260812 06:16:41.474967 21908 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36628
I20260812 06:16:41.484815 21908 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36640:
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:16:41.503038 22080 tablet_service.cc:1511] Processing CreateTablet for tablet edee5ab7ed764ae8bfa482f13c370331 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0590a4531d304f91a166454921765d75]), partition=
I20260812 06:16:41.503515 22080 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet edee5ab7ed764ae8bfa482f13c370331. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:41.506028 22169 tablet_bootstrap.cc:492] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Bootstrap starting.
I20260812 06:16:41.507020 22169 tablet_bootstrap.cc:654] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:41.508296 22169 tablet_bootstrap.cc:492] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: No bootstrap required, opened a new log
I20260812 06:16:41.508464 22169 ts_tablet_manager.cc:1403] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:41.508958 22169 raft_consensus.cc:359] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "917cd9dc8438404d84c31ae10ff00064" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 44419 } }
I20260812 06:16:41.509061 22169 raft_consensus.cc:385] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:41.509084 22169 raft_consensus.cc:740] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 917cd9dc8438404d84c31ae10ff00064, State: Initialized, Role: FOLLOWER
I20260812 06:16:41.509244 22169 consensus_queue.cc:260] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [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: "917cd9dc8438404d84c31ae10ff00064" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 44419 } }
I20260812 06:16:41.509334 22169 raft_consensus.cc:399] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:41.509382 22169 raft_consensus.cc:493] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:41.509438 22169 raft_consensus.cc:3060] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:41.510221 22169 raft_consensus.cc:515] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "917cd9dc8438404d84c31ae10ff00064" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 44419 } }
I20260812 06:16:41.510437 22169 leader_election.cc:304] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [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: 917cd9dc8438404d84c31ae10ff00064; no voters: 
I20260812 06:16:41.510691 22169 leader_election.cc:290] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:41.510787 22173 raft_consensus.cc:2804] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:41.510988 22173 raft_consensus.cc:697] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 1 LEADER]: Becoming Leader. State: Replica: 917cd9dc8438404d84c31ae10ff00064, State: Running, Role: LEADER
I20260812 06:16:41.511067 22169 ts_tablet_manager.cc:1434] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:41.511178 22173 consensus_queue.cc:237] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [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: "917cd9dc8438404d84c31ae10ff00064" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 44419 } }
I20260812 06:16:41.511438 22150 heartbeater.cc:499] Master 127.21.86.190:46415 was elected leader, sending a full tablet report...
I20260812 06:16:41.514010 21907 catalog_manager.cc:5719] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 reported cstate change: term changed from 0 to 1, leader changed from <none> to 917cd9dc8438404d84c31ae10ff00064 (127.21.86.129). New cstate: current_term: 1 leader_uuid: "917cd9dc8438404d84c31ae10ff00064" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "917cd9dc8438404d84c31ae10ff00064" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 44419 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:41.585954 21850 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.020s	sys 0.007s
I20260812 06:16:41.712985 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushMRSOp(edee5ab7ed764ae8bfa482f13c370331): perf score=15.086190
I20260812 06:16:41.888159 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushMRSOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.175s	user 0.143s	sys 0.020s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":217,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":749,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41663,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":136,"threads_started":1,"update_count":1450}
I20260812 06:16:41.889287 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling LogGCOp(edee5ab7ed764ae8bfa482f13c370331): free 20743880 bytes of WAL
I20260812 06:16:41.889590 22042 log_reader.cc:385] T edee5ab7ed764ae8bfa482f13c370331: removed 2 log segments from log reader
I20260812 06:16:41.889679 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000001 (ops 1-6)
I20260812 06:16:41.889744 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000002 (ops 7-11)
I20260812 06:16:41.894438 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: LogGCOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:41.894866 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=2.188937
I20260812 06:16:41.914759 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.020s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.915231 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:42.044226 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.129s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":662,"lbm_read_time_us":9215,"lbm_reads_lt_1ms":454,"lbm_write_time_us":25180,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":290,"threads_started":5,"update_count":1950}
I20260812 06:16:42.044744 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:42.082551 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.038s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16742,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.082995 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling UndoDeltaBlockGCOp(edee5ab7ed764ae8bfa482f13c370331): 12719217 bytes on disk
I20260812 06:16:42.083555 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: UndoDeltaBlockGCOp(edee5ab7ed764ae8bfa482f13c370331) 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:16:42.083958 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:42.196458 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.112s	user 0.100s	sys 0.013s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":207,"lbm_read_time_us":7321,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22804,"lbm_writes_lt_1ms":343,"mutex_wait_us":41,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":1500}
I20260812 06:16:42.197180 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:42.234594 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.037s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15295,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.235071 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:42.348464 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.113s	user 0.077s	sys 0.036s 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":430,"lbm_read_time_us":8165,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18363,"lbm_writes_lt_1ms":343,"mutex_wait_us":108,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":1500}
I20260812 06:16:42.349020 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:42.396283 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.047s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17297,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.397003 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=2.188937
I20260812 06:16:42.412590 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.413188 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:42.546501 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.133s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":946,"lbm_read_time_us":9659,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23592,"lbm_writes_lt_1ms":443,"mutex_wait_us":386,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.547122 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:42.599385 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.052s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21184,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.599888 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=2.188937
I20260812 06:16:42.615213 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.615823 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:42.733354 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.117s	user 0.075s	sys 0.040s 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":523,"lbm_read_time_us":8615,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21937,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:42.734102 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:42.786466 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.051s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17799,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.787086 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=2.188937
I20260812 06:16:42.797818 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.798298 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:42.976891 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.178s	user 0.087s	sys 0.061s 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":223,"lbm_read_time_us":11013,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24654,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:16:42.977466 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=11.118625
I20260812 06:16:43.193738 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.216s	user 0.034s	sys 0.006s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":73989,"lbm_writes_1-10_ms":1,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.194626 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:43.297231 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.102s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.297763 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:43.400676 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.103s	user 0.011s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8147,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.401216 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:43.499871 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.098s	user 0.017s	sys 0.020s Metrics: {"bytes_written":11897251,"delete_count":0,"lbm_write_time_us":16532,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:43.500739 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:43.601338 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.100s	user 0.012s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11568,"lbm_writes_lt_1ms":203,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1000}
I20260812 06:16:43.602150 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:43.707619 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.105s	user 0.013s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9016,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.708315 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:43.811776 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.103s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.812733 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:43.918272 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.105s	user 0.006s	sys 0.017s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9993,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.918728 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=7.149875
I20260812 06:16:44.021709 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.103s	user 0.018s	sys 0.007s Metrics: {"bytes_written":8820441,"delete_count":0,"lbm_write_time_us":11426,"lbm_writes_lt_1ms":218,"reinsert_count":0,"update_count":1075}
I20260812 06:16:44.022557 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:44.124197 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.101s	user 0.026s	sys 0.004s Metrics: {"bytes_written":11692138,"delete_count":0,"lbm_write_time_us":13269,"lbm_writes_lt_1ms":288,"reinsert_count":0,"update_count":1425}
I20260812 06:16:44.124842 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=7.149875
I20260812 06:16:44.222664 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.098s	user 0.023s	sys 0.004s Metrics: {"bytes_written":8902493,"delete_count":0,"lbm_write_time_us":11464,"lbm_writes_lt_1ms":220,"reinsert_count":0,"update_count":1085}
I20260812 06:16:44.223414 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:44.325691 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.102s	user 0.024s	sys 0.012s Metrics: {"bytes_written":11610078,"delete_count":0,"lbm_write_time_us":16666,"lbm_writes_lt_1ms":286,"mutex_wait_us":18,"reinsert_count":0,"update_count":1415}
I20260812 06:16:44.326292 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:44.423573 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.097s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9341,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.424465 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=7.149875
I20260812 06:16:44.528331 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.104s	user 0.021s	sys 0.007s Metrics: {"bytes_written":8451226,"delete_count":0,"lbm_write_time_us":12622,"lbm_writes_lt_1ms":209,"reinsert_count":0,"update_count":1030}
I20260812 06:16:44.529129 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=7.149875
I20260812 06:16:44.638067 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.109s	user 0.011s	sys 0.012s Metrics: {"bytes_written":8369178,"delete_count":0,"lbm_write_time_us":8599,"lbm_writes_lt_1ms":207,"reinsert_count":0,"update_count":1020}
I20260812 06:16:44.638716 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:44.736814 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.098s	user 0.022s	sys 0.009s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":14118,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:44.737673 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:44.835450 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.098s	user 0.014s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10355,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.836226 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:44.933917 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.097s	user 0.010s	sys 0.015s Metrics: {"bytes_written":8328151,"delete_count":0,"lbm_write_time_us":11304,"lbm_writes_lt_1ms":206,"mutex_wait_us":158,"reinsert_count":0,"update_count":1015}
I20260812 06:16:44.934876 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:45.037825 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.103s	user 0.018s	sys 0.002s Metrics: {"bytes_written":8246107,"delete_count":0,"lbm_write_time_us":8669,"lbm_writes_lt_1ms":204,"reinsert_count":0,"update_count":1005}
I20260812 06:16:45.038671 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:45.145509 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.107s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12143397,"delete_count":0,"lbm_write_time_us":13536,"lbm_writes_lt_1ms":299,"reinsert_count":0,"update_count":1480}
I20260812 06:16:45.146579 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:45.247646 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.101s	user 0.022s	sys 0.004s Metrics: {"bytes_written":8492251,"delete_count":0,"lbm_write_time_us":11660,"lbm_writes_lt_1ms":210,"reinsert_count":0,"update_count":1035}
I20260812 06:16:45.248333 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=7.149875
I20260812 06:16:45.347458 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.099s	user 0.024s	sys 0.000s Metrics: {"bytes_written":8492256,"delete_count":0,"lbm_write_time_us":10781,"lbm_writes_lt_1ms":210,"reinsert_count":0,"update_count":1035}
I20260812 06:16:45.348009 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:45.450919 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.103s	user 0.026s	sys 0.006s Metrics: {"bytes_written":11733150,"delete_count":0,"lbm_write_time_us":13524,"lbm_writes_lt_1ms":289,"reinsert_count":0,"update_count":1430}
I20260812 06:16:45.452207 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:45.552284 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.099s	user 0.023s	sys 0.007s Metrics: {"bytes_written":8410203,"delete_count":0,"lbm_write_time_us":13210,"lbm_writes_lt_1ms":208,"reinsert_count":0,"update_count":1025}
I20260812 06:16:45.553340 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=7.149875
I20260812 06:16:45.647815 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.094s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8410202,"delete_count":0,"lbm_write_time_us":9682,"lbm_writes_lt_1ms":208,"reinsert_count":0,"update_count":1025}
I20260812 06:16:45.648345 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=6.157687
I20260812 06:16:45.668453 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8366,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:45.669028 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=2.188937
I20260812 06:16:45.682814 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.683719 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushMRSOp(edee5ab7ed764ae8bfa482f13c370331): perf score=2.187753
I20260812 06:16:45.723935 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushMRSOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.040s	user 0.038s	sys 0.000s Metrics: {"bytes_written":3406500,"cfile_init":1,"dirs.queue_time_us":216,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":1416,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3055,"lbm_writes_lt_1ms":49,"peak_mem_usage":0,"rows_written":83,"thread_start_us":83,"threads_started":1}
I20260812 06:16:45.724871 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling LogGCOp(edee5ab7ed764ae8bfa482f13c370331): free 341328423 bytes of WAL
I20260812 06:16:45.725286 22042 log_reader.cc:385] T edee5ab7ed764ae8bfa482f13c370331: removed 34 log segments from log reader
I20260812 06:16:45.725353 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000003 (ops 12-16)
I20260812 06:16:45.725414 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000004 (ops 17-21)
I20260812 06:16:45.725457 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000005 (ops 22-26)
I20260812 06:16:45.725502 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000006 (ops 27-31)
I20260812 06:16:45.725544 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000007 (ops 32-36)
I20260812 06:16:45.725585 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000008 (ops 37-40)
I20260812 06:16:45.725625 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000009 (ops 41-45)
I20260812 06:16:45.725663 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000010 (ops 46-50)
I20260812 06:16:45.725695 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000011 (ops 51-55)
I20260812 06:16:45.725741 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000012 (ops 56-60)
I20260812 06:16:45.725785 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000013 (ops 61-65)
I20260812 06:16:45.725822 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000014 (ops 66-70)
I20260812 06:16:45.725864 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000015 (ops 71-74)
I20260812 06:16:45.725906 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000016 (ops 75-79)
I20260812 06:16:45.725950 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000017 (ops 80-84)
I20260812 06:16:45.725991 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000018 (ops 85-89)
I20260812 06:16:45.726032 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000019 (ops 90-94)
I20260812 06:16:45.726070 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000020 (ops 95-98)
I20260812 06:16:45.726110 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000021 (ops 99-103)
I20260812 06:16:45.726155 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000022 (ops 104-108)
I20260812 06:16:45.726209 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000023 (ops 109-113)
I20260812 06:16:45.726275 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000024 (ops 114-118)
I20260812 06:16:45.726321 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000025 (ops 119-123)
I20260812 06:16:45.726366 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000026 (ops 124-128)
I20260812 06:16:45.726392 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000027 (ops 129-133)
I20260812 06:16:45.726415 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000028 (ops 134-138)
I20260812 06:16:45.726437 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000029 (ops 139-142)
I20260812 06:16:45.726459 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000030 (ops 143-147)
I20260812 06:16:45.726480 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000031 (ops 148-152)
I20260812 06:16:45.726501 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000032 (ops 153-156)
I20260812 06:16:45.726543 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000033 (ops 157-161)
I20260812 06:16:45.726579 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000034 (ops 162-166)
I20260812 06:16:45.726617 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000035 (ops 167-171)
I20260812 06:16:45.726651 22042 log.cc:1079] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/edee5ab7ed764ae8bfa482f13c370331/wal-000000036 (ops 172-176)
I20260812 06:16:45.805727 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: LogGCOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.081s	user 0.004s	sys 0.073s Metrics: {}
I20260812 06:16:45.806367 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling UndoDeltaBlockGCOp(edee5ab7ed764ae8bfa482f13c370331): 1070 bytes on disk
I20260812 06:16:45.807006 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: UndoDeltaBlockGCOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.807555 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331): perf score=10.126437
I20260812 06:16:45.844777 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: FlushDeltaMemStoresOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 0.037s	user 0.008s	sys 0.024s Metrics: {"bytes_written":11856225,"delete_count":0,"lbm_write_time_us":16183,"lbm_writes_lt_1ms":292,"reinsert_count":0,"update_count":1445}
I20260812 06:16:45.845371 22151 maintenance_manager.cc:419] P 917cd9dc8438404d84c31ae10ff00064: Scheduling MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331): perf score=1.000000
I20260812 06:16:46.656881 21850 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.071s	user 1.797s	sys 0.169s
I20260812 06:16:48.729209 22064 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Scan from 127.0.0.1:49586 (request call id 202) took 2068 ms. Trace:
I20260812 06:16:48.729342 22064 rpcz_store.cc:276] 0812 06:16:46.660382 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:16:46.660496 (+   114us) service_pool.cc:224] Handling call
0812 06:16:46.661404 (+   908us) tablet_service.cc:2890] Created scanner 7384588d46d7442e8b264e77905dbb33 for tablet edee5ab7ed764ae8bfa482f13c370331, query id is e5ce9293e99e46f09f42b277c082219b
0812 06:16:46.662567 (+  1163us) tablet_service.cc:3030] Creating iterator
0812 06:16:46.662669 (+   102us) tablet_service.cc:3408] Waiting safe time to advance
0812 06:16:46.662714 (+    45us) tablet_service.cc:3415] Waiting for operations to commit
0812 06:16:46.662756 (+    42us) tablet_service.cc:3431] All operations in snapshot committed. Waited for 72 microseconds
0812 06:16:46.662908 (+   152us) tablet_service.cc:3055] Iterator created
0812 06:16:48.668931 (+2006023us) tablet_service.cc:3077] Iterator init: OK
0812 06:16:48.669023 (+    92us) tablet_service.cc:3120] has_more: true
0812 06:16:48.669186 (+   163us) tablet_service.cc:3137] Continuing scan request
0812 06:16:48.669382 (+   196us) tablet_service.cc:3201] Found scanner 7384588d46d7442e8b264e77905dbb33 for tablet edee5ab7ed764ae8bfa482f13c370331, query id is e5ce9293e99e46f09f42b277c082219b
0812 06:16:48.729184 (+ 59802us) inbound_call.cc:177] Queueing success response
Metrics: {"cfile_cache_hit":41,"cfile_cache_hit_bytes":1400330,"cfile_cache_miss":6510,"cfile_cache_miss_bytes":269071187,"cfile_init":6,"delta_iterators_relevant":34,"lbm_read_time_us":149897,"lbm_reads_1-10_ms":8,"lbm_reads_lt_1ms":6526,"rowset_iterators":2,"scanner_bytes_read":2950785}
W20260812 06:16:48.733358 21850 scanner-internal.cc:458] Time spent opening tablet: real 2.075s	user 0.002s	sys 0.000s
I20260812 06:16:48.735469 21850 heavy-update-compaction-itest.cc:265] Time spent scanning: real 2.078s	user 0.004s	sys 0.000s
I20260812 06:16:48.736076 21850 tablet_server.cc:179] TabletServer@127.21.86.129:0 shutting down...
I20260812 06:16:49.566196 22042 maintenance_manager.cc:643] P 917cd9dc8438404d84c31ae10ff00064: MajorDeltaCompactionOp(edee5ab7ed764ae8bfa482f13c370331) complete. Timing: real 3.721s	user 1.181s	sys 2.533s Metrics: {"cfile_cache_miss":6547,"cfile_cache_miss_bytes":270471306,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":28,"delta_iterators_relevant":28,"dirs.queue_time_us":1234,"lbm_read_time_us":110682,"lbm_reads_lt_1ms":6575,"lbm_write_time_us":1202343,"lbm_writes_1-10_ms":10,"lbm_writes_lt_1ms":6527,"peak_mem_usage":807218451,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":3891,"threads_started":8,"update_count":32445,"wal-append.queue_time_us":3259}
I20260812 06:16:49.567003 21850 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:49.567438 21850 tablet_replica.cc:333] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064: stopping tablet replica
I20260812 06:16:49.567699 21850 raft_consensus.cc:2243] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:49.567906 21850 raft_consensus.cc:2272] T edee5ab7ed764ae8bfa482f13c370331 P 917cd9dc8438404d84c31ae10ff00064 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:49.595163 21850 tablet_server.cc:196] TabletServer@127.21.86.129:0 shutdown complete.
I20260812 06:16:50.604779 21850 master.cc:562] Master@127.21.86.190:46415 shutting down...
I20260812 06:16:50.609766 21850 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.609961 21850 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.610052 21850 tablet_replica.cc:333] T 00000000000000000000000000000000 P 81c4eb2bca514682be0209f55e059b82: stopping tablet replica
I20260812 06:16:50.622742 21850 master.cc:584] Master@127.21.86.190:46415 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (9380 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:50.764742 21850 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.86.190:44003
I20260812 06:16:50.765192 21850 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:50.767300 21850 server_base.cc:1061] running on GCE node
W20260812 06:16:50.767310 22211 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:50.767310 22209 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:16:50.767478 22217 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:16:50.767796 21850 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:50.767860 21850 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:16:50.767887 21850 hybrid_clock.cc:648] HybridClock initialized: now 1786515410767887 us; error 0 us; skew 500 ppm
I20260812 06:16:50.768807 21850 webserver.cc:533] Webserver started at http://127.21.86.190:36283/ using document root <none> and password file <none>
I20260812 06:16:50.768985 21850 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:50.769057 21850 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:50.769166 21850 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:50.769567 21850 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/master-0-root/instance:
uuid: "35b7b2b8d5ec43779cc451b85f718727"
format_stamp: "Formatted at 2026-08-12 06:16:50 on dist-test-slave-7nm7"
I20260812 06:16:50.771178 21850 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:50.772081 22223 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:16:50.772331 21850 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:50.772423 21850 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/master-0-root
uuid: "35b7b2b8d5ec43779cc451b85f718727"
format_stamp: "Formatted at 2026-08-12 06:16:50 on dist-test-slave-7nm7"
I20260812 06:16:50.772505 21850 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-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:16:50.783118 21850 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:50.783514 21850 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:50.788044 21850 rpc_server.cc:307] RPC server started. Bound to: 127.21.86.190:44003
I20260812 06:16:50.813809 22327 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.86.190:44003 every 8 connection(s)
I20260812 06:16:50.814419 22330 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:16:50.816267 22330 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727: Bootstrap starting.
I20260812 06:16:50.817082 22330 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:50.818168 22330 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727: No bootstrap required, opened a new log
I20260812 06:16:50.818660 22330 raft_consensus.cc:359] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35b7b2b8d5ec43779cc451b85f718727" member_type: VOTER }
I20260812 06:16:50.818750 22330 raft_consensus.cc:385] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:50.818773 22330 raft_consensus.cc:740] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 35b7b2b8d5ec43779cc451b85f718727, State: Initialized, Role: FOLLOWER
I20260812 06:16:50.818954 22330 consensus_queue.cc:260] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [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: "35b7b2b8d5ec43779cc451b85f718727" member_type: VOTER }
I20260812 06:16:50.819027 22330 raft_consensus.cc:399] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:50.819051 22330 raft_consensus.cc:493] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:50.819104 22330 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:50.819837 22330 raft_consensus.cc:515] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35b7b2b8d5ec43779cc451b85f718727" member_type: VOTER }
I20260812 06:16:50.819984 22330 leader_election.cc:304] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [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: 35b7b2b8d5ec43779cc451b85f718727; no voters: 
I20260812 06:16:50.820214 22330 leader_election.cc:290] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:50.820379 22334 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:50.820605 22334 raft_consensus.cc:697] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 1 LEADER]: Becoming Leader. State: Replica: 35b7b2b8d5ec43779cc451b85f718727, State: Running, Role: LEADER
I20260812 06:16:50.820704 22330 sys_catalog.cc:565] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:50.820760 22334 consensus_queue.cc:237] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [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: "35b7b2b8d5ec43779cc451b85f718727" member_type: VOTER }
I20260812 06:16:50.821250 22338 sys_catalog.cc:455] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 35b7b2b8d5ec43779cc451b85f718727. Latest consensus state: current_term: 1 leader_uuid: "35b7b2b8d5ec43779cc451b85f718727" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35b7b2b8d5ec43779cc451b85f718727" member_type: VOTER } }
I20260812 06:16:50.821347 22338 sys_catalog.cc:458] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:50.821236 22336 sys_catalog.cc:455] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "35b7b2b8d5ec43779cc451b85f718727" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35b7b2b8d5ec43779cc451b85f718727" member_type: VOTER } }
I20260812 06:16:50.821403 22336 sys_catalog.cc:458] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:50.821707 22348 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:50.822734 22348 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:50.823087 21850 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:50.824880 22348 catalog_manager.cc:1383] Generated new cluster ID: 374c78bf304645a5aeb7368998c28d0f
I20260812 06:16:50.824946 22348 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:50.832448 22348 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:50.833055 22348 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:50.844367 22348 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727: Generated new TSK 0
I20260812 06:16:50.844594 22348 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:50.855661 21850 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:50.857970 22366 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:50.858093 21850 server_base.cc:1061] running on GCE node
W20260812 06:16:50.858134 22374 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:16:50.858335 22368 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:16:50.858589 21850 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:50.858671 21850 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:16:50.858707 21850 hybrid_clock.cc:648] HybridClock initialized: now 1786515410858706 us; error 0 us; skew 500 ppm
I20260812 06:16:50.859575 21850 webserver.cc:533] Webserver started at http://127.21.86.129:46733/ using document root <none> and password file <none>
I20260812 06:16:50.859860 21850 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:50.859946 21850 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:50.860025 21850 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:50.860477 21850 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/instance:
uuid: "948fde7553714c97b912a94fe351e210"
format_stamp: "Formatted at 2026-08-12 06:16:50 on dist-test-slave-7nm7"
I20260812 06:16:50.862035 21850 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:50.863238 22387 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:16:50.863627 21850 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:50.863822 21850 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root
uuid: "948fde7553714c97b912a94fe351e210"
format_stamp: "Formatted at 2026-08-12 06:16:50 on dist-test-slave-7nm7"
I20260812 06:16:50.863920 21850 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-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:16:50.869347 21850 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:50.869799 21850 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:50.870191 21850 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:50.870882 21850 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:50.870946 21850 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:50.870999 21850 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:50.871071 21850 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:50.877465 21850 rpc_server.cc:307] RPC server started. Bound to: 127.21.86.129:43285
I20260812 06:16:50.877686 22498 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.86.129:43285 every 8 connection(s)
I20260812 06:16:50.883723 22499 heartbeater.cc:344] Connected to a master server at 127.21.86.190:44003
I20260812 06:16:50.883884 22499 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:50.884172 22499 heartbeater.cc:507] Master 127.21.86.190:44003 requested a full tablet report, sending...
I20260812 06:16:50.885037 22258 ts_manager.cc:194] Registered new tserver with Master: 948fde7553714c97b912a94fe351e210 (127.21.86.129:43285)
I20260812 06:16:50.885823 22258 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47396
I20260812 06:16:50.886059 21850 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007954995s
I20260812 06:16:50.894737 22258 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47406:
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:16:50.905984 22430 tablet_service.cc:1511] Processing CreateTablet for tablet 25ea7d1010254ff9892d891893f8c0b5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=530856ea5a544fd08a85b35644c6a96e]), partition=
I20260812 06:16:50.906386 22430 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 25ea7d1010254ff9892d891893f8c0b5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:50.908877 22522 tablet_bootstrap.cc:492] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Bootstrap starting.
I20260812 06:16:50.909665 22522 tablet_bootstrap.cc:654] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:50.911167 22522 tablet_bootstrap.cc:492] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: No bootstrap required, opened a new log
I20260812 06:16:50.911273 22522 ts_tablet_manager.cc:1403] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:50.911746 22522 raft_consensus.cc:359] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "948fde7553714c97b912a94fe351e210" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 43285 } }
I20260812 06:16:50.911835 22522 raft_consensus.cc:385] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:50.911859 22522 raft_consensus.cc:740] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 948fde7553714c97b912a94fe351e210, State: Initialized, Role: FOLLOWER
I20260812 06:16:50.911998 22522 consensus_queue.cc:260] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [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: "948fde7553714c97b912a94fe351e210" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 43285 } }
I20260812 06:16:50.912087 22522 raft_consensus.cc:399] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:50.912111 22522 raft_consensus.cc:493] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:50.912142 22522 raft_consensus.cc:3060] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:50.912842 22522 raft_consensus.cc:515] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "948fde7553714c97b912a94fe351e210" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 43285 } }
I20260812 06:16:50.912955 22522 leader_election.cc:304] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [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: 948fde7553714c97b912a94fe351e210; no voters: 
I20260812 06:16:50.913110 22522 leader_election.cc:290] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:50.913394 22522 ts_tablet_manager.cc:1434] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:50.913503 22528 raft_consensus.cc:2804] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:50.913614 22499 heartbeater.cc:499] Master 127.21.86.190:44003 was elected leader, sending a full tablet report...
I20260812 06:16:50.913689 22528 raft_consensus.cc:697] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 1 LEADER]: Becoming Leader. State: Replica: 948fde7553714c97b912a94fe351e210, State: Running, Role: LEADER
I20260812 06:16:50.913945 22528 consensus_queue.cc:237] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [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: "948fde7553714c97b912a94fe351e210" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 43285 } }
I20260812 06:16:50.916532 22258 catalog_manager.cc:5719] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 reported cstate change: term changed from 0 to 1, leader changed from <none> to 948fde7553714c97b912a94fe351e210 (127.21.86.129). New cstate: current_term: 1 leader_uuid: "948fde7553714c97b912a94fe351e210" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "948fde7553714c97b912a94fe351e210" member_type: VOTER last_known_addr { host: "127.21.86.129" port: 43285 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:50.979410 21850 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.010s	sys 0.013s
I20260812 06:16:51.129053 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5): perf score=19.054940
I20260812 06:16:51.292932 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.164s	user 0.105s	sys 0.053s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":795,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44450,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:51.293768 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling LogGCOp(25ea7d1010254ff9892d891893f8c0b5): free 20743880 bytes of WAL
I20260812 06:16:51.293988 22394 log_reader.cc:385] T 25ea7d1010254ff9892d891893f8c0b5: removed 2 log segments from log reader
I20260812 06:16:51.294030 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000001 (ops 1-6)
I20260812 06:16:51.294059 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000002 (ops 7-11)
I20260812 06:16:51.298862 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: LogGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:51.299225 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5): 16411395 bytes on disk
I20260812 06:16:51.299639 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:51.300063 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:51.318368 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.018s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.318883 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:51.479064 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.160s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":62,"lbm_read_time_us":11554,"lbm_reads_lt_1ms":460,"lbm_write_time_us":27975,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"thread_start_us":338,"threads_started":5,"update_count":2000}
I20260812 06:16:51.479702 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:51.531962 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.052s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22765,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.532428 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:51.544023 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.544472 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:51.724157 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.180s	user 0.109s	sys 0.064s 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":1342,"lbm_read_time_us":12132,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33661,"lbm_writes_lt_1ms":543,"mutex_wait_us":438,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45440,"update_count":2500}
I20260812 06:16:51.724663 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:51.776656 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.052s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24031,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.777098 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:51.946218 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.169s	user 0.114s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":325,"lbm_read_time_us":11458,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28858,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:51.946763 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=11.118625
I20260812 06:16:51.983433 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.036s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16941,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:51.983950 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:52.001955 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.018s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5366,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:52.002590 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:52.154945 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.152s	user 0.122s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":9318,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27384,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":64896,"update_count":2000}
I20260812 06:16:52.155581 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:52.210209 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.054s	user 0.033s	sys 0.008s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20299,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.210814 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:52.223095 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.223574 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:52.397673 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.174s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1143,"lbm_read_time_us":14877,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35162,"lbm_writes_lt_1ms":543,"mutex_wait_us":359,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:16:52.398420 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=11.118625
I20260812 06:16:52.448540 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":22583,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:52.449034 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:52.460438 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:52.461011 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:52.600162 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.139s	user 0.115s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":11123,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26753,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:16:52.600790 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=10.126437
I20260812 06:16:52.658386 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.057s	user 0.023s	sys 0.032s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19299,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:52.658988 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:52.670523 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.670989 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:52.715667 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.045s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1317,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1732,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:52.716323 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling LogGCOp(25ea7d1010254ff9892d891893f8c0b5): free 124710292 bytes of WAL
I20260812 06:16:52.716543 22394 log_reader.cc:385] T 25ea7d1010254ff9892d891893f8c0b5: removed 12 log segments from log reader
I20260812 06:16:52.716585 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000003 (ops 12-16)
I20260812 06:16:52.716621 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000004 (ops 17-21)
I20260812 06:16:52.716691 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000005 (ops 22-26)
I20260812 06:16:52.716722 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000006 (ops 27-31)
I20260812 06:16:52.716763 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000007 (ops 32-36)
I20260812 06:16:52.716791 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000008 (ops 37-41)
I20260812 06:16:52.716828 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000009 (ops 42-46)
I20260812 06:16:52.716871 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000010 (ops 47-51)
I20260812 06:16:52.716905 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000011 (ops 52-56)
I20260812 06:16:52.716944 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000012 (ops 57-61)
I20260812 06:16:52.716984 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000013 (ops 62-66)
I20260812 06:16:52.717023 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000014 (ops 67-71)
I20260812 06:16:52.747040 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: LogGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:52.747430 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=3.181125
I20260812 06:16:52.760854 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:52.761389 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5): 472 bytes on disk
I20260812 06:16:52.761778 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:52.762173 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:52.772192 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:52.772601 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:53.009657 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.237s	user 0.143s	sys 0.091s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1089,"lbm_read_time_us":16326,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37515,"lbm_writes_lt_1ms":643,"mutex_wait_us":266,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:16:53.010473 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=15.087375
I20260812 06:16:53.077378 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.067s	user 0.025s	sys 0.024s Metrics: {"bytes_written":17394483,"delete_count":0,"lbm_write_time_us":26590,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":426,"reinsert_count":0,"update_count":2120}
I20260812 06:16:53.077905 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=5.165500
I20260812 06:16:53.097658 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":7220504,"delete_count":0,"lbm_write_time_us":8587,"lbm_writes_lt_1ms":179,"reinsert_count":0,"update_count":880}
I20260812 06:16:53.098124 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:53.328665 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.230s	user 0.152s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":16814,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37248,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":3000}
I20260812 06:16:53.329402 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=18.063937
I20260812 06:16:53.403651 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.074s	user 0.062s	sys 0.004s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30082,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:53.404114 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:53.415977 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.416733 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:53.634362 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.217s	user 0.131s	sys 0.086s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":16769,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35785,"lbm_writes_lt_1ms":643,"mutex_wait_us":4,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:53.635054 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:53.683108 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21498,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.683880 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:53.698474 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5970,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.698939 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:53.872028 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.173s	user 0.137s	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":137,"lbm_read_time_us":12769,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30441,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:16:53.872651 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:53.933398 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.060s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16574001,"delete_count":0,"lbm_write_time_us":27299,"lbm_writes_lt_1ms":407,"reinsert_count":0,"update_count":2020}
I20260812 06:16:53.933890 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:53.947789 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4902,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:16:53.948315 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:54.133072 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.185s	user 0.114s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":871,"lbm_read_time_us":12530,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32763,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:54.133718 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=15.087375
I20260812 06:16:54.194710 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.061s	user 0.025s	sys 0.034s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21641,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:54.195348 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=3.181125
I20260812 06:16:54.212348 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":5251341,"delete_count":0,"lbm_write_time_us":6582,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:16:54.212911 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.196750
I20260812 06:16:54.223722 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3842,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:16:54.224373 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:54.262363 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.038s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1226,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1496,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:54.263065 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling LogGCOp(25ea7d1010254ff9892d891893f8c0b5): free 120553348 bytes of WAL
I20260812 06:16:54.263332 22394 log_reader.cc:385] T 25ea7d1010254ff9892d891893f8c0b5: removed 12 log segments from log reader
I20260812 06:16:54.263399 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000015 (ops 72-76)
I20260812 06:16:54.263440 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000016 (ops 77-80)
I20260812 06:16:54.263474 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000017 (ops 81-85)
I20260812 06:16:54.263504 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000018 (ops 86-90)
I20260812 06:16:54.263535 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000019 (ops 91-95)
I20260812 06:16:54.263569 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000020 (ops 96-100)
I20260812 06:16:54.263602 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000021 (ops 101-104)
I20260812 06:16:54.263640 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000022 (ops 105-109)
I20260812 06:16:54.263664 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000023 (ops 110-114)
I20260812 06:16:54.263684 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000024 (ops 115-119)
I20260812 06:16:54.263720 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000025 (ops 120-124)
I20260812 06:16:54.263753 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000026 (ops 125-129)
I20260812 06:16:54.297714 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: LogGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.034s	user 0.001s	sys 0.030s Metrics: {}
I20260812 06:16:54.298117 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5): 473 bytes on disk
I20260812 06:16:54.298595 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.299104 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:54.323504 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.024s	user 0.006s	sys 0.004s 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:16:54.323940 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:54.334496 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.334914 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:54.593636 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.259s	user 0.186s	sys 0.072s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082242,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":208,"lbm_read_time_us":21579,"lbm_reads_lt_1ms":875,"lbm_write_time_us":46886,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":79,"threads_started":1,"update_count":4000}
I20260812 06:16:54.594208 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=18.063937
I20260812 06:16:54.654498 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.060s	user 0.039s	sys 0.021s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":26781,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:54.655110 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:54.671938 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.672353 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:54.856362 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.184s	user 0.135s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":343,"lbm_read_time_us":13889,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38026,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:54.856933 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:54.908155 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.051s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20783,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.908712 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:54.921924 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.922429 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:55.096450 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.174s	user 0.120s	sys 0.044s 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":140,"lbm_read_time_us":12934,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31083,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:16:55.097141 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:55.142546 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.045s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19916,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.143067 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:55.303777 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.160s	user 0.124s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":205,"lbm_read_time_us":12634,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27355,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:16:55.304572 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=10.126437
I20260812 06:16:55.341699 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.037s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16705,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.342206 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:55.354526 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4732,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.354954 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:55.487226 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.132s	user 0.085s	sys 0.044s 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":154,"lbm_read_time_us":8298,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25863,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22528,"update_count":2000}
I20260812 06:16:55.488113 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=10.126437
I20260812 06:16:55.531446 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.043s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15254,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.532047 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:55.544333 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.545097 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:55.676044 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.130s	user 0.100s	sys 0.031s 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":71,"lbm_read_time_us":10152,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24851,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:16:55.677016 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=10.126437
I20260812 06:16:55.716730 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.039s	user 0.011s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15392,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.717296 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:55.728016 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.011s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.728711 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:55.760070 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushMRSOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1285,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1908,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:55.760842 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling LogGCOp(25ea7d1010254ff9892d891893f8c0b5): free 124710621 bytes of WAL
I20260812 06:16:55.761169 22394 log_reader.cc:385] T 25ea7d1010254ff9892d891893f8c0b5: removed 12 log segments from log reader
I20260812 06:16:55.761240 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000027 (ops 130-134)
I20260812 06:16:55.761289 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000028 (ops 135-139)
I20260812 06:16:55.761348 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000029 (ops 140-144)
I20260812 06:16:55.761391 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000030 (ops 145-149)
I20260812 06:16:55.761430 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000031 (ops 150-154)
I20260812 06:16:55.761471 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000032 (ops 155-159)
I20260812 06:16:55.761510 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000033 (ops 160-164)
I20260812 06:16:55.761551 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000034 (ops 165-169)
I20260812 06:16:55.761591 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000035 (ops 170-174)
I20260812 06:16:55.761631 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000036 (ops 175-179)
I20260812 06:16:55.761668 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000037 (ops 180-184)
I20260812 06:16:55.761708 22394 log.cc:1079] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: Deleting log segment in path: /tmp/dist-test-taskFHRUNp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401325760-21850-0/minicluster-data/ts-0-root/wals/25ea7d1010254ff9892d891893f8c0b5/wal-000000038 (ops 185-189)
I20260812 06:16:55.793927 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: LogGCOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:55.794417 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=3.181125
I20260812 06:16:55.812007 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7171,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:55.812495 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:55.823310 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3880,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:55.823859 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:56.006634 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.183s	user 0.128s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":717,"lbm_read_time_us":14731,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36938,"lbm_writes_lt_1ms":643,"mutex_wait_us":326,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:16:56.007393 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=14.095187
I20260812 06:16:56.057791 21850 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.078s	user 1.886s	sys 0.178s
I20260812 06:16:56.061138 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.054s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.061537 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5): 462 bytes on disk
I20260812 06:16:56.061878 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: UndoDeltaBlockGCOp(25ea7d1010254ff9892d891893f8c0b5) 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:16:56.062405 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5): perf score=2.188937
I20260812 06:16:56.072275 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: FlushDeltaMemStoresOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.072610 22501 maintenance_manager.cc:419] P 948fde7553714c97b912a94fe351e210: Scheduling MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5): perf score=1.000000
I20260812 06:16:56.105770 21850 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.048s	user 0.000s	sys 0.000s
I20260812 06:16:56.106385 21850 tablet_server.cc:179] TabletServer@127.21.86.129:0 shutting down...
I20260812 06:16:56.184826 22394 maintenance_manager.cc:643] P 948fde7553714c97b912a94fe351e210: MajorDeltaCompactionOp(25ea7d1010254ff9892d891893f8c0b5) complete. Timing: real 0.112s	user 0.092s	sys 0.020s Metrics: {"cfile_cache_hit":401,"cfile_cache_hit_bytes":16409768,"cfile_cache_miss":131,"cfile_cache_miss_bytes":8364921,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":4155,"lbm_reads_lt_1ms":163,"lbm_write_time_us":26354,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:16:56.185667 21850 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:56.185910 21850 tablet_replica.cc:333] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210: stopping tablet replica
I20260812 06:16:56.186049 21850 raft_consensus.cc:2243] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:56.186308 21850 raft_consensus.cc:2272] T 25ea7d1010254ff9892d891893f8c0b5 P 948fde7553714c97b912a94fe351e210 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:56.190284 21850 tablet_server.cc:196] TabletServer@127.21.86.129:0 shutdown complete.
I20260812 06:16:56.231077 21850 master.cc:562] Master@127.21.86.190:44003 shutting down...
I20260812 06:16:56.234480 21850 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:56.234668 21850 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:56.234751 21850 tablet_replica.cc:333] T 00000000000000000000000000000000 P 35b7b2b8d5ec43779cc451b85f718727: stopping tablet replica
I20260812 06:16:56.247350 21850 master.cc:584] Master@127.21.86.190:44003 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5626 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (15007 ms total)

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