[==========] 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:54.480901 24578 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.0.190:42193
I20260812 06:16:54.481930 24578 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:54.482544 24578 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:54.489140 24589 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:54.489140 24595 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:54.489298 24578 server_base.cc:1061] running on GCE node
W20260812 06:16:54.489431 24591 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:54.489903 24578 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:54.490023 24578 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:54.490080 24578 hybrid_clock.cc:648] HybridClock initialized: now 1786515414490078 us; error 0 us; skew 500 ppm
I20260812 06:16:54.491875 24578 webserver.cc:533] Webserver started at http://127.24.0.190:33769/ using document root <none> and password file <none>
I20260812 06:16:54.492413 24578 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:54.492527 24578 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:54.492811 24578 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:54.494412 24578 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/master-0-root/instance:
uuid: "6a6aaea8cd6543e19a0caa5686d96ba2"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-44d2"
I20260812 06:16:54.497908 24578 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:54.500102 24606 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:54.501171 24578 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:54.501315 24578 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/master-0-root
uuid: "6a6aaea8cd6543e19a0caa5686d96ba2"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-44d2"
I20260812 06:16:54.501418 24578 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-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:54.522368 24578 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:54.523041 24578 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:54.523228 24578 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:54.530944 24578 rpc_server.cc:307] RPC server started. Bound to: 127.24.0.190:42193
I20260812 06:16:54.530958 24677 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.0.190:42193 every 8 connection(s)
I20260812 06:16:54.533874 24679 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:54.539706 24679 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2: Bootstrap starting.
I20260812 06:16:54.542435 24679 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:54.543593 24679 log.cc:826] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:54.545451 24679 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2: No bootstrap required, opened a new log
I20260812 06:16:54.548254 24679 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a6aaea8cd6543e19a0caa5686d96ba2" member_type: VOTER }
I20260812 06:16:54.548447 24679 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:54.548568 24679 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6a6aaea8cd6543e19a0caa5686d96ba2, State: Initialized, Role: FOLLOWER
I20260812 06:16:54.549268 24679 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [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: "6a6aaea8cd6543e19a0caa5686d96ba2" member_type: VOTER }
I20260812 06:16:54.549444 24679 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:54.549515 24679 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:54.549654 24679 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:54.550467 24679 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a6aaea8cd6543e19a0caa5686d96ba2" member_type: VOTER }
I20260812 06:16:54.550920 24679 leader_election.cc:304] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [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: 6a6aaea8cd6543e19a0caa5686d96ba2; no voters: 
I20260812 06:16:54.551290 24679 leader_election.cc:290] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:54.551412 24683 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:54.551687 24683 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 1 LEADER]: Becoming Leader. State: Replica: 6a6aaea8cd6543e19a0caa5686d96ba2, State: Running, Role: LEADER
I20260812 06:16:54.552150 24683 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [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: "6a6aaea8cd6543e19a0caa5686d96ba2" member_type: VOTER }
I20260812 06:16:54.552381 24679 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:54.554098 24686 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6a6aaea8cd6543e19a0caa5686d96ba2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a6aaea8cd6543e19a0caa5686d96ba2" member_type: VOTER } }
I20260812 06:16:54.554112 24687 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6a6aaea8cd6543e19a0caa5686d96ba2. Latest consensus state: current_term: 1 leader_uuid: "6a6aaea8cd6543e19a0caa5686d96ba2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a6aaea8cd6543e19a0caa5686d96ba2" member_type: VOTER } }
I20260812 06:16:54.554245 24686 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:54.554244 24687 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:54.554603 24704 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:54.554894 24578 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:54.556980 24704 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:54.561286 24704 catalog_manager.cc:1383] Generated new cluster ID: b2a519c0cbe24e6faa41d0eff32849a1
I20260812 06:16:54.561347 24704 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:54.572305 24704 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:54.573143 24704 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:54.581246 24704 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2: Generated new TSK 0
I20260812 06:16:54.581852 24704 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:54.587316 24578 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:54.589994 24724 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:54.590011 24719 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:54.590015 24720 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:54.590371 24578 server_base.cc:1061] running on GCE node
I20260812 06:16:54.590552 24578 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:54.590600 24578 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:54.590623 24578 hybrid_clock.cc:648] HybridClock initialized: now 1786515414590623 us; error 0 us; skew 500 ppm
I20260812 06:16:54.591570 24578 webserver.cc:533] Webserver started at http://127.24.0.129:43607/ using document root <none> and password file <none>
I20260812 06:16:54.591740 24578 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:54.591799 24578 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:54.591874 24578 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:54.592312 24578 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/instance:
uuid: "86f0812aec164d48a8bf75d6f955c1d4"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-44d2"
I20260812 06:16:54.594205 24578 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:16:54.595322 24732 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:54.595643 24578 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:54.595713 24578 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root
uuid: "86f0812aec164d48a8bf75d6f955c1d4"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-44d2"
I20260812 06:16:54.595809 24578 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-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:54.616675 24578 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:54.617174 24578 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:54.617708 24578 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:54.618572 24578 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:54.618623 24578 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:54.618665 24578 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:54.618726 24578 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:54.625630 24578 rpc_server.cc:307] RPC server started. Bound to: 127.24.0.129:33021
I20260812 06:16:54.625667 24828 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.0.129:33021 every 8 connection(s)
I20260812 06:16:54.635790 24830 heartbeater.cc:344] Connected to a master server at 127.24.0.190:42193
I20260812 06:16:54.636021 24830 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:54.636471 24830 heartbeater.cc:507] Master 127.24.0.190:42193 requested a full tablet report, sending...
I20260812 06:16:54.638039 24626 ts_manager.cc:194] Registered new tserver with Master: 86f0812aec164d48a8bf75d6f955c1d4 (127.24.0.129:33021)
I20260812 06:16:54.638582 24578 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012308533s
I20260812 06:16:54.639595 24626 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46758
I20260812 06:16:54.654743 24626 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46774:
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:54.669167 24766 tablet_service.cc:1511] Processing CreateTablet for tablet 9027ac4cf2b247ad8f1236ad7b921251 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8b6411e9cb0d45e38ae928af12404d02]), partition=
I20260812 06:16:54.669639 24766 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9027ac4cf2b247ad8f1236ad7b921251. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:54.672751 24852 tablet_bootstrap.cc:492] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Bootstrap starting.
I20260812 06:16:54.673815 24852 tablet_bootstrap.cc:654] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:54.675045 24852 tablet_bootstrap.cc:492] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: No bootstrap required, opened a new log
I20260812 06:16:54.675186 24852 ts_tablet_manager.cc:1403] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:54.675670 24852 raft_consensus.cc:359] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86f0812aec164d48a8bf75d6f955c1d4" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 33021 } }
I20260812 06:16:54.675810 24852 raft_consensus.cc:385] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:54.675868 24852 raft_consensus.cc:740] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 86f0812aec164d48a8bf75d6f955c1d4, State: Initialized, Role: FOLLOWER
I20260812 06:16:54.676051 24852 consensus_queue.cc:260] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [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: "86f0812aec164d48a8bf75d6f955c1d4" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 33021 } }
I20260812 06:16:54.676172 24852 raft_consensus.cc:399] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:54.676249 24852 raft_consensus.cc:493] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:54.676311 24852 raft_consensus.cc:3060] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:54.677302 24852 raft_consensus.cc:515] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86f0812aec164d48a8bf75d6f955c1d4" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 33021 } }
I20260812 06:16:54.677491 24852 leader_election.cc:304] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [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: 86f0812aec164d48a8bf75d6f955c1d4; no voters: 
I20260812 06:16:54.677754 24852 leader_election.cc:290] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:54.677881 24856 raft_consensus.cc:2804] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:54.678164 24852 ts_tablet_manager.cc:1434] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:54.678313 24830 heartbeater.cc:499] Master 127.24.0.190:42193 was elected leader, sending a full tablet report...
I20260812 06:16:54.678154 24856 raft_consensus.cc:697] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 1 LEADER]: Becoming Leader. State: Replica: 86f0812aec164d48a8bf75d6f955c1d4, State: Running, Role: LEADER
I20260812 06:16:54.678779 24856 consensus_queue.cc:237] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [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: "86f0812aec164d48a8bf75d6f955c1d4" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 33021 } }
I20260812 06:16:54.681810 24626 catalog_manager.cc:5719] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 86f0812aec164d48a8bf75d6f955c1d4 (127.24.0.129). New cstate: current_term: 1 leader_uuid: "86f0812aec164d48a8bf75d6f955c1d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86f0812aec164d48a8bf75d6f955c1d4" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 33021 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:54.752221 24578 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.016s	sys 0.013s
I20260812 06:16:54.876789 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=15.086190
I20260812 06:16:55.008322 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.131s	user 0.115s	sys 0.012s Metrics: {"bytes_written":8656347,"cfile_init":1,"compiler_manager_pool.queue_time_us":353,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":865,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32000,"lbm_writes_lt_1ms":578,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":178048,"thread_start_us":169,"threads_started":1,"update_count":1055}
I20260812 06:16:55.009608 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling LogGCOp(9027ac4cf2b247ad8f1236ad7b921251): free 20743880 bytes of WAL
I20260812 06:16:55.009946 24737 log_reader.cc:385] T 9027ac4cf2b247ad8f1236ad7b921251: removed 2 log segments from log reader
I20260812 06:16:55.010046 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000001 (ops 1-6)
I20260812 06:16:55.010128 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000002 (ops 7-11)
I20260812 06:16:55.015565 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: LogGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:55.016180 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:55.030848 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":4809,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:16:55.031392 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:55.158627 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.127s	user 0.093s	sys 0.024s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16159605,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1268,"lbm_read_time_us":5974,"lbm_reads_lt_1ms":354,"lbm_write_time_us":20425,"lbm_writes_lt_1ms":333,"mutex_wait_us":296,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":349,"threads_started":5,"update_count":1450}
I20260812 06:16:55.159178 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:55.209398 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.050s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17284,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.209848 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251): 12719216 bytes on disk
I20260812 06:16:55.210314 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:55.210721 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:55.221794 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.222249 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:55.345973 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.124s	user 0.082s	sys 0.041s 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":696,"lbm_read_time_us":8950,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22238,"lbm_writes_lt_1ms":443,"mutex_wait_us":243,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:16:55.346518 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:55.399559 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.053s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15769,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.400220 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:55.413409 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.413906 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:55.593122 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.179s	user 0.120s	sys 0.058s 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":1560,"lbm_read_time_us":13101,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31333,"lbm_writes_lt_1ms":443,"mutex_wait_us":549,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:16:55.593829 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:55.637732 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.044s	user 0.024s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18950,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.638291 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:55.656807 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.657388 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:55.786638 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.129s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":562,"lbm_read_time_us":7360,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24737,"lbm_writes_lt_1ms":443,"mutex_wait_us":336,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:16:55.787392 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:55.835906 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.048s	user 0.012s	sys 0.032s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":23828,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:16:55.836541 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:55.850221 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.850739 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:55.974892 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.124s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":915,"lbm_read_time_us":7676,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24161,"lbm_writes_lt_1ms":443,"mutex_wait_us":467,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:55.975575 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:56.024217 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.048s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16473,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.024945 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:56.035808 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.036377 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:56.188519 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.152s	user 0.111s	sys 0.040s 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":592,"lbm_read_time_us":11069,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25801,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2000}
I20260812 06:16:56.189137 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:56.238087 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.049s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18790,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.238544 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:56.248749 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.249513 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:56.370632 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.121s	user 0.106s	sys 0.014s 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":2081,"lbm_read_time_us":8638,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23599,"lbm_writes_lt_1ms":443,"mutex_wait_us":533,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:16:56.371363 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:56.415906 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.044s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20940,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:56.416465 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:56.427202 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.427863 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:56.461688 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1602,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1463,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:56.462512 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling LogGCOp(9027ac4cf2b247ad8f1236ad7b921251): free 120553383 bytes of WAL
I20260812 06:16:56.462764 24737 log_reader.cc:385] T 9027ac4cf2b247ad8f1236ad7b921251: removed 12 log segments from log reader
I20260812 06:16:56.462809 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000003 (ops 12-16)
I20260812 06:16:56.462838 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000004 (ops 17-21)
I20260812 06:16:56.462894 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000005 (ops 22-26)
I20260812 06:16:56.462939 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000006 (ops 27-31)
I20260812 06:16:56.462997 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000007 (ops 32-36)
I20260812 06:16:56.463045 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000008 (ops 37-40)
I20260812 06:16:56.463091 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000009 (ops 41-45)
I20260812 06:16:56.463135 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000010 (ops 46-50)
I20260812 06:16:56.463174 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000011 (ops 51-55)
I20260812 06:16:56.463215 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000012 (ops 56-60)
I20260812 06:16:56.463255 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000013 (ops 61-64)
I20260812 06:16:56.463294 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000014 (ops 65-69)
I20260812 06:16:56.490705 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: LogGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:56.491262 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=4.173312
I20260812 06:16:56.507392 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":6442,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:16:56.507910 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.196750
I20260812 06:16:56.520123 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:16:56.520785 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251): 472 bytes on disk
I20260812 06:16:56.521347 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:16:56.521966 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:56.704008 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.182s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":785,"lbm_read_time_us":13001,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34030,"lbm_writes_lt_1ms":643,"mutex_wait_us":89,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20864,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:16:56.704664 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=14.095187
I20260812 06:16:56.757045 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.052s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21362,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.757614 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:56.769631 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.012s	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:56.770164 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:56.942934 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.173s	user 0.119s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":379,"lbm_read_time_us":12059,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31929,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:16:56.943605 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=14.095187
I20260812 06:16:56.987534 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19610,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.988330 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:57.146653 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.158s	user 0.113s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":146,"lbm_read_time_us":11289,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24025,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":80128,"update_count":2000}
I20260812 06:16:57.147343 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=14.095187
I20260812 06:16:57.208324 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.061s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21633,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.208984 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:57.220119 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.220757 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:57.388026 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.167s	user 0.082s	sys 0.085s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":14101,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28542,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:57.388831 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=11.118625
I20260812 06:16:57.423858 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.035s	user 0.021s	sys 0.010s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14627,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:57.424644 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:57.450944 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.026s	user 0.009s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5906,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.451548 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:57.622560 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.171s	user 0.109s	sys 0.051s 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":990,"lbm_read_time_us":10021,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25660,"lbm_writes_lt_1ms":443,"mutex_wait_us":258,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.623185 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=14.095187
I20260812 06:16:57.672045 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.049s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.672582 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:57.683964 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.684579 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:57.833899 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.149s	user 0.128s	sys 0.020s 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":582,"lbm_read_time_us":10960,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32097,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:16:57.834755 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=11.118625
I20260812 06:16:57.866016 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13752,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:57.866515 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:57.886274 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6289,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.886804 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:57.941481 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.054s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":134,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1511,"drs_written":1,"lbm_read_time_us":129,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2182,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:57.942427 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling LogGCOp(9027ac4cf2b247ad8f1236ad7b921251): free 120553388 bytes of WAL
I20260812 06:16:57.942713 24737 log_reader.cc:385] T 9027ac4cf2b247ad8f1236ad7b921251: removed 12 log segments from log reader
I20260812 06:16:57.942792 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000015 (ops 70-74)
I20260812 06:16:57.942845 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000016 (ops 75-79)
I20260812 06:16:57.942904 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000017 (ops 80-84)
I20260812 06:16:57.942946 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000018 (ops 85-89)
I20260812 06:16:57.942981 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000019 (ops 90-94)
I20260812 06:16:57.943017 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000020 (ops 95-99)
I20260812 06:16:57.943053 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000021 (ops 100-104)
I20260812 06:16:57.943109 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000022 (ops 105-108)
I20260812 06:16:57.943151 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000023 (ops 109-113)
I20260812 06:16:57.943188 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000024 (ops 114-118)
I20260812 06:16:57.943229 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000025 (ops 119-122)
I20260812 06:16:57.943266 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000026 (ops 123-127)
I20260812 06:16:57.973131 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: LogGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:57.973578 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251): 472 bytes on disk
I20260812 06:16:57.974033 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.974591 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=7.149875
I20260812 06:16:57.999545 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.025s	user 0.020s	sys 0.001s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10415,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:58.000173 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:58.024748 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.024s	user 0.008s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5074,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.025547 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:58.252785 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.227s	user 0.147s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2781,"lbm_read_time_us":16437,"lbm_reads_lt_1ms":766,"lbm_write_time_us":37763,"lbm_writes_lt_1ms":743,"mutex_wait_us":2181,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:16:58.253458 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=18.063937
I20260812 06:16:58.323769 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.070s	user 0.047s	sys 0.019s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25708,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:58.324424 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:58.339921 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.340394 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:58.528774 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.188s	user 0.127s	sys 0.061s 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":1426,"lbm_read_time_us":14003,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32447,"lbm_writes_lt_1ms":643,"mutex_wait_us":316,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:58.529422 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=14.095187
I20260812 06:16:58.581991 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.052s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22144,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.582538 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:58.591840 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.009s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1395006,"delete_count":0,"lbm_write_time_us":1505,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:16:58.592406 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.196750
I20260812 06:16:58.603514 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:16:58.604070 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:58.793012 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.189s	user 0.127s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774713,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":286,"lbm_read_time_us":13855,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34134,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:16:58.793867 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=11.118625
I20260812 06:16:58.844973 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.051s	user 0.026s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18605,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:58.845558 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:58.855697 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3768,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.856163 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:59.017482 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.161s	user 0.101s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":11460,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26186,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.018030 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:59.065544 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.047s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17456,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.066179 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:59.078250 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.079180 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:59.212195 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.133s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":10907,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23465,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":81536,"update_count":2000}
I20260812 06:16:59.212908 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:59.263433 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.050s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16499,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.263907 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:59.274259 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.274766 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:59.401856 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.126s	user 0.103s	sys 0.022s 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":326,"lbm_read_time_us":8210,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.402588 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=10.126437
I20260812 06:16:59.456887 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.054s	user 0.033s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20707,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.457495 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:59.468310 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.468930 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:59.498534 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushMRSOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.029s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1447,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:59.499389 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:59.701820 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.202s	user 0.115s	sys 0.070s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":11018,"lbm_reads_lt_1ms":464,"lbm_write_time_us":56380,"lbm_writes_1-10_ms":15,"lbm_writes_lt_1ms":428,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:16:59.702759 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling LogGCOp(9027ac4cf2b247ad8f1236ad7b921251): free 124710514 bytes of WAL
I20260812 06:16:59.703094 24737 log_reader.cc:385] T 9027ac4cf2b247ad8f1236ad7b921251: removed 12 log segments from log reader
I20260812 06:16:59.703156 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000027 (ops 128-132)
I20260812 06:16:59.703208 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000028 (ops 133-137)
I20260812 06:16:59.703272 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000029 (ops 138-142)
I20260812 06:16:59.703372 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000030 (ops 143-147)
I20260812 06:16:59.703430 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000031 (ops 148-152)
I20260812 06:16:59.703482 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000032 (ops 153-157)
I20260812 06:16:59.703529 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000033 (ops 158-162)
I20260812 06:16:59.703578 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000034 (ops 163-167)
I20260812 06:16:59.703627 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000035 (ops 168-172)
I20260812 06:16:59.703675 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000036 (ops 173-177)
I20260812 06:16:59.703722 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000037 (ops 178-182)
I20260812 06:16:59.703770 24737 log.cc:1079] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/9027ac4cf2b247ad8f1236ad7b921251/wal-000000038 (ops 183-187)
I20260812 06:16:59.735246 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: LogGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:59.735931 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251): 463 bytes on disk
I20260812 06:16:59.736528 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: UndoDeltaBlockGCOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.737353 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=15.087375
I20260812 06:16:59.789099 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.052s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23749,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:16:59.789634 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:59.816004 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.026s	user 0.006s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.816581 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=2.188937
I20260812 06:16:59.826462 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: FlushDeltaMemStoresOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3733,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.826951 24831 maintenance_manager.cc:419] P 86f0812aec164d48a8bf75d6f955c1d4: Scheduling MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251): perf score=1.000000
I20260812 06:16:59.890395 24578 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.138s	user 1.850s	sys 0.194s
I20260812 06:16:59.985255 24578 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.003s	sys 0.000s
I20260812 06:16:59.985951 24578 tablet_server.cc:179] TabletServer@127.24.0.129:0 shutting down...
I20260812 06:17:00.008085 24737 maintenance_manager.cc:643] P 86f0812aec164d48a8bf75d6f955c1d4: MajorDeltaCompactionOp(9027ac4cf2b247ad8f1236ad7b921251) complete. Timing: real 0.181s	user 0.133s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":439,"lbm_read_time_us":13701,"lbm_reads_lt_1ms":669,"lbm_write_time_us":28983,"lbm_writes_lt_1ms":643,"mutex_wait_us":80,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":3000}
I20260812 06:17:00.009444 24578 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:00.009953 24578 tablet_replica.cc:333] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4: stopping tablet replica
I20260812 06:17:00.010257 24578 raft_consensus.cc:2243] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:00.010537 24578 raft_consensus.cc:2272] T 9027ac4cf2b247ad8f1236ad7b921251 P 86f0812aec164d48a8bf75d6f955c1d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:00.028925 24578 tablet_server.cc:196] TabletServer@127.24.0.129:0 shutdown complete.
I20260812 06:17:00.061679 24578 master.cc:562] Master@127.24.0.190:42193 shutting down...
I20260812 06:17:00.065127 24578 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:00.065333 24578 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:00.065433 24578 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6a6aaea8cd6543e19a0caa5686d96ba2: stopping tablet replica
I20260812 06:17:00.077674 24578 master.cc:584] Master@127.24.0.190:42193 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5688 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:00.184013 24578 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.0.190:42283
I20260812 06:17:00.184412 24578 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:00.187259 24889 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:00.187273 24892 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:00.187424 24887 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:00.187611 24578 server_base.cc:1061] running on GCE node
I20260812 06:17:00.187793 24578 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:00.187834 24578 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:00.187849 24578 hybrid_clock.cc:648] HybridClock initialized: now 1786515420187849 us; error 0 us; skew 500 ppm
I20260812 06:17:00.188819 24578 webserver.cc:533] Webserver started at http://127.24.0.190:36415/ using document root <none> and password file <none>
I20260812 06:17:00.189065 24578 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:00.189122 24578 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:00.189229 24578 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:00.189652 24578 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/master-0-root/instance:
uuid: "b0764f77d25a43678442de51d658f170"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-44d2"
I20260812 06:17:00.191313 24578 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:00.192361 24899 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.192689 24578 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:00.192760 24578 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/master-0-root
uuid: "b0764f77d25a43678442de51d658f170"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-44d2"
I20260812 06:17:00.192854 24578 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:00.212811 24578 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:00.213271 24578 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:00.217550 24578 rpc_server.cc:307] RPC server started. Bound to: 127.24.0.190:42283
I20260812 06:17:00.220180 24971 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:00.220618 24970 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.0.190:42283 every 8 connection(s)
I20260812 06:17:00.222899 24971 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170: Bootstrap starting.
I20260812 06:17:00.223726 24971 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:00.224774 24971 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170: No bootstrap required, opened a new log
I20260812 06:17:00.225195 24971 raft_consensus.cc:359] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0764f77d25a43678442de51d658f170" member_type: VOTER }
I20260812 06:17:00.225281 24971 raft_consensus.cc:385] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:00.225343 24971 raft_consensus.cc:740] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b0764f77d25a43678442de51d658f170, State: Initialized, Role: FOLLOWER
I20260812 06:17:00.225535 24971 consensus_queue.cc:260] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [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: "b0764f77d25a43678442de51d658f170" member_type: VOTER }
I20260812 06:17:00.225612 24971 raft_consensus.cc:399] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:00.225672 24971 raft_consensus.cc:493] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:00.225731 24971 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:00.226421 24971 raft_consensus.cc:515] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0764f77d25a43678442de51d658f170" member_type: VOTER }
I20260812 06:17:00.226562 24971 leader_election.cc:304] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [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: b0764f77d25a43678442de51d658f170; no voters: 
I20260812 06:17:00.226778 24971 leader_election.cc:290] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:00.227023 24978 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:00.227200 24978 raft_consensus.cc:697] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 1 LEADER]: Becoming Leader. State: Replica: b0764f77d25a43678442de51d658f170, State: Running, Role: LEADER
I20260812 06:17:00.227274 24971 sys_catalog.cc:565] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:00.227335 24978 consensus_queue.cc:237] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [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: "b0764f77d25a43678442de51d658f170" member_type: VOTER }
I20260812 06:17:00.227813 24977 sys_catalog.cc:455] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b0764f77d25a43678442de51d658f170" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0764f77d25a43678442de51d658f170" member_type: VOTER } }
I20260812 06:17:00.227849 24980 sys_catalog.cc:455] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b0764f77d25a43678442de51d658f170. Latest consensus state: current_term: 1 leader_uuid: "b0764f77d25a43678442de51d658f170" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0764f77d25a43678442de51d658f170" member_type: VOTER } }
I20260812 06:17:00.228057 24980 sys_catalog.cc:458] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:00.228338 24977 sys_catalog.cc:458] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:00.228681 24992 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:00.229393 24992 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:00.229712 24578 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:00.231411 24992 catalog_manager.cc:1383] Generated new cluster ID: 2fb13ec82aa544afb6ba550a102d4ab7
I20260812 06:17:00.231474 24992 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:00.237043 24992 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:00.237607 24992 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:00.250497 24992 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170: Generated new TSK 0
I20260812 06:17:00.250718 24992 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:00.262235 24578 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:00.264405 25012 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:00.264403 25009 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:00.264400 25016 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:00.264647 24578 server_base.cc:1061] running on GCE node
I20260812 06:17:00.264964 24578 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:00.265021 24578 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:00.265069 24578 hybrid_clock.cc:648] HybridClock initialized: now 1786515420265059 us; error 0 us; skew 500 ppm
I20260812 06:17:00.265914 24578 webserver.cc:533] Webserver started at http://127.24.0.129:34859/ using document root <none> and password file <none>
I20260812 06:17:00.266135 24578 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:00.266199 24578 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:00.266306 24578 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:00.266753 24578 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/instance:
uuid: "26818799499147a1bbd97625d08c4dbd"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-44d2"
I20260812 06:17:00.268306 24578 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:00.269332 25022 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.269626 24578 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:00.269718 24578 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root
uuid: "26818799499147a1bbd97625d08c4dbd"
format_stamp: "Formatted at 2026-08-12 06:17:00 on dist-test-slave-44d2"
I20260812 06:17:00.269802 24578 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:00.274675 24578 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:00.274993 24578 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:00.275313 24578 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:00.275761 24578 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:00.275821 24578 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.275866 24578 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:00.275892 24578 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:00.280314 24578 rpc_server.cc:307] RPC server started. Bound to: 127.24.0.129:38037
I20260812 06:17:00.281662 25118 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.0.129:38037 every 8 connection(s)
I20260812 06:17:00.286316 25120 heartbeater.cc:344] Connected to a master server at 127.24.0.190:42283
I20260812 06:17:00.286442 25120 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:00.286687 25120 heartbeater.cc:507] Master 127.24.0.190:42283 requested a full tablet report, sending...
I20260812 06:17:00.287377 24921 ts_manager.cc:194] Registered new tserver with Master: 26818799499147a1bbd97625d08c4dbd (127.24.0.129:38037)
I20260812 06:17:00.288028 24578 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006695058s
I20260812 06:17:00.288144 24921 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54656
I20260812 06:17:00.295456 24921 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54666:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:00.304575 25063 tablet_service.cc:1511] Processing CreateTablet for tablet 35a401734fd34191b1263070d9008eb4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2bcc3005ae9d4304915697d92b63ac69]), partition=
I20260812 06:17:00.304836 25063 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 35a401734fd34191b1263070d9008eb4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:00.306756 25137 tablet_bootstrap.cc:492] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Bootstrap starting.
I20260812 06:17:00.307703 25137 tablet_bootstrap.cc:654] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:00.308818 25137 tablet_bootstrap.cc:492] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: No bootstrap required, opened a new log
I20260812 06:17:00.308920 25137 ts_tablet_manager.cc:1403] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:00.309324 25137 raft_consensus.cc:359] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "26818799499147a1bbd97625d08c4dbd" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 38037 } }
I20260812 06:17:00.309409 25137 raft_consensus.cc:385] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:00.309471 25137 raft_consensus.cc:740] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 26818799499147a1bbd97625d08c4dbd, State: Initialized, Role: FOLLOWER
I20260812 06:17:00.309628 25137 consensus_queue.cc:260] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [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: "26818799499147a1bbd97625d08c4dbd" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 38037 } }
I20260812 06:17:00.309748 25137 raft_consensus.cc:399] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:00.309803 25137 raft_consensus.cc:493] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:00.309862 25137 raft_consensus.cc:3060] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:00.310722 25137 raft_consensus.cc:515] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "26818799499147a1bbd97625d08c4dbd" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 38037 } }
I20260812 06:17:00.310842 25137 leader_election.cc:304] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [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: 26818799499147a1bbd97625d08c4dbd; no voters: 
I20260812 06:17:00.310993 25137 leader_election.cc:290] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:00.311136 25139 raft_consensus.cc:2804] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:00.311269 25139 raft_consensus.cc:697] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 1 LEADER]: Becoming Leader. State: Replica: 26818799499147a1bbd97625d08c4dbd, State: Running, Role: LEADER
I20260812 06:17:00.311311 25120 heartbeater.cc:499] Master 127.24.0.190:42283 was elected leader, sending a full tablet report...
I20260812 06:17:00.311308 25137 ts_tablet_manager.cc:1434] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:00.311410 25139 consensus_queue.cc:237] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [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: "26818799499147a1bbd97625d08c4dbd" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 38037 } }
I20260812 06:17:00.312860 24921 catalog_manager.cc:5719] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd reported cstate change: term changed from 0 to 1, leader changed from <none> to 26818799499147a1bbd97625d08c4dbd (127.24.0.129). New cstate: current_term: 1 leader_uuid: "26818799499147a1bbd97625d08c4dbd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "26818799499147a1bbd97625d08c4dbd" member_type: VOTER last_known_addr { host: "127.24.0.129" port: 38037 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:00.383303 24578 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.018s	sys 0.007s
I20260812 06:17:00.532207 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushMRSOp(35a401734fd34191b1263070d9008eb4): perf score=19.054940
I20260812 06:17:00.697167 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushMRSOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.165s	user 0.128s	sys 0.035s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":932,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38089,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:00.698055 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling LogGCOp(35a401734fd34191b1263070d9008eb4): free 20290830 bytes of WAL
I20260812 06:17:00.698355 25031 log_reader.cc:385] T 35a401734fd34191b1263070d9008eb4: removed 2 log segments from log reader
I20260812 06:17:00.698419 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000001 (ops 1-6)
I20260812 06:17:00.698477 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000002 (ops 7-10)
I20260812 06:17:00.703192 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: LogGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:00.703613 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:00.718127 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5349,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.718766 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4): 16411393 bytes on disk
I20260812 06:17:00.719394 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.719923 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:00.871296 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.151s	user 0.099s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":595,"lbm_read_time_us":10965,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24793,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":337,"threads_started":5,"update_count":2000}
I20260812 06:17:00.872061 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=11.118625
I20260812 06:17:00.903081 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.031s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13536,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:00.903551 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:00.914876 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3568,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.915364 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:01.046415 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.131s	user 0.100s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1314,"lbm_read_time_us":8821,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25110,"lbm_writes_lt_1ms":443,"mutex_wait_us":366,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":56576,"update_count":2000}
I20260812 06:17:01.047238 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:01.093780 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.046s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21470,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.094297 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:01.106014 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.012s	user 0.010s	sys 0.000s 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:17:01.106515 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:01.240813 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.134s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":9057,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25975,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:17:01.241628 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:01.286075 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.044s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15304,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.286599 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:01.297283 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.297798 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:01.444013 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.146s	user 0.110s	sys 0.034s 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":181,"lbm_read_time_us":10234,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28743,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:01.444921 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:01.489468 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.044s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14875,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.490168 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:01.613202 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.123s	user 0.079s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":420,"lbm_read_time_us":7756,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17700,"lbm_writes_lt_1ms":343,"mutex_wait_us":40,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":1500}
I20260812 06:17:01.613973 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:01.651841 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.038s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16203,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.652343 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:01.667531 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.668360 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:01.800437 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.132s	user 0.086s	sys 0.045s 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":719,"lbm_read_time_us":9885,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24840,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:17:01.801260 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:01.846774 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.045s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.847362 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:01.861635 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.862198 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:01.989043 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":10014,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24060,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:17:01.989893 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:02.039244 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.049s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15990,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.039794 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:02.050678 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.051211 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushMRSOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:02.099658 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushMRSOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.048s	user 0.033s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1679,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2065,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:02.100244 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling LogGCOp(35a401734fd34191b1263070d9008eb4): free 121006375 bytes of WAL
I20260812 06:17:02.100536 25031 log_reader.cc:385] T 35a401734fd34191b1263070d9008eb4: removed 12 log segments from log reader
I20260812 06:17:02.100595 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000003 (ops 11-15)
I20260812 06:17:02.100627 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000004 (ops 16-20)
I20260812 06:17:02.100692 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000005 (ops 21-25)
I20260812 06:17:02.100721 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000006 (ops 26-30)
I20260812 06:17:02.100760 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000007 (ops 31-35)
I20260812 06:17:02.100785 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000008 (ops 36-40)
I20260812 06:17:02.100865 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000009 (ops 41-44)
I20260812 06:17:02.100898 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000010 (ops 45-49)
I20260812 06:17:02.100934 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000011 (ops 50-54)
I20260812 06:17:02.100975 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000012 (ops 55-59)
I20260812 06:17:02.101034 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000013 (ops 60-64)
I20260812 06:17:02.101074 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000014 (ops 65-69)
I20260812 06:17:02.126188 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: LogGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:02.126601 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:02.149736 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.023s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6605,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.150189 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4): 482 bytes on disk
I20260812 06:17:02.150588 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.151064 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:02.161464 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.162098 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:02.386013 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.224s	user 0.157s	sys 0.065s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":482,"lbm_read_time_us":14915,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38974,"lbm_writes_lt_1ms":643,"mutex_wait_us":86,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17152,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:17:02.386926 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=15.087375
I20260812 06:17:02.437791 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.051s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":22406,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:02.438370 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:02.461607 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.023s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6055,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":450}
I20260812 06:17:02.462090 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:02.474206 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.474890 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:02.708005 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.233s	user 0.135s	sys 0.085s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":199,"lbm_read_time_us":17483,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34394,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":3000}
I20260812 06:17:02.708896 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=18.063937
I20260812 06:17:02.769426 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.060s	user 0.038s	sys 0.017s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25260,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:02.770160 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:02.955894 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.185s	user 0.118s	sys 0.065s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":998,"lbm_read_time_us":15062,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":562,"lbm_write_time_us":32102,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:02.956619 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=18.063937
I20260812 06:17:03.021520 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.065s	user 0.036s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.022217 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:03.039331 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5411,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.039808 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:03.273730 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.234s	user 0.142s	sys 0.090s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":14806,"lbm_reads_lt_1ms":664,"lbm_write_time_us":40446,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":3000}
I20260812 06:17:03.274421 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=18.063937
I20260812 06:17:03.355080 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.080s	user 0.045s	sys 0.028s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":37993,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.355677 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:03.366737 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.367466 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:03.572949 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.205s	user 0.130s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1081,"lbm_read_time_us":15012,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37629,"lbm_writes_lt_1ms":643,"mutex_wait_us":333,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:17:03.573810 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=14.095187
I20260812 06:17:03.643585 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.070s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25648,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.644132 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=6.157687
I20260812 06:17:03.670390 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.026s	user 0.015s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10484,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:03.671031 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushMRSOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:03.721829 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushMRSOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.051s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1727,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2374,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:03.722568 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling LogGCOp(35a401734fd34191b1263070d9008eb4): free 128867509 bytes of WAL
I20260812 06:17:03.722815 25031 log_reader.cc:385] T 35a401734fd34191b1263070d9008eb4: removed 13 log segments from log reader
I20260812 06:17:03.722882 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000015 (ops 70-74)
I20260812 06:17:03.722931 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000016 (ops 75-78)
I20260812 06:17:03.722985 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000017 (ops 79-83)
I20260812 06:17:03.723014 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000018 (ops 84-88)
I20260812 06:17:03.723054 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000019 (ops 89-93)
I20260812 06:17:03.723095 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000020 (ops 94-98)
I20260812 06:17:03.723133 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000021 (ops 99-103)
I20260812 06:17:03.723172 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000022 (ops 104-108)
I20260812 06:17:03.723210 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000023 (ops 109-112)
I20260812 06:17:03.723249 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000024 (ops 113-117)
I20260812 06:17:03.723285 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000025 (ops 118-122)
I20260812 06:17:03.723326 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000026 (ops 123-126)
I20260812 06:17:03.723364 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000027 (ops 127-131)
I20260812 06:17:03.750371 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: LogGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.028s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:17:03.750851 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4): 493 bytes on disk
I20260812 06:17:03.751391 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.752104 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=7.149875
I20260812 06:17:03.775032 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9941,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:03.775576 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling LogGCOp(35a401734fd34191b1263070d9008eb4): free 12017954 bytes of WAL
I20260812 06:17:03.775830 25031 log_reader.cc:385] T 35a401734fd34191b1263070d9008eb4: removed 1 log segments from log reader
I20260812 06:17:03.775894 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000028 (ops 132-136)
I20260812 06:17:03.779109 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: LogGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:03.779453 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=2.188937
I20260812 06:17:03.795255 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.795815 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:04.148916 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.353s	user 0.158s	sys 0.117s Metrics: {"cfile_cache_miss":934,"cfile_cache_miss_bytes":41184566,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":46,"lbm_read_time_us":23713,"lbm_reads_lt_1ms":966,"lbm_write_time_us":51237,"lbm_writes_lt_1ms":943,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":18944,"thread_start_us":393,"threads_started":6,"update_count":4500}
I20260812 06:17:04.149791 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=26.993625
I20260812 06:17:04.256425 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.106s	user 0.038s	sys 0.035s Metrics: {"bytes_written":29127374,"delete_count":0,"lbm_write_time_us":34225,"lbm_writes_lt_1ms":713,"reinsert_count":0,"update_count":3550}
I20260812 06:17:04.257050 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:04.347223 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.090s	user 0.026s	sys 0.011s Metrics: {"bytes_written":11897250,"delete_count":0,"lbm_write_time_us":15963,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:17:04.348898 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=6.157687
I20260812 06:17:04.449781 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.101s	user 0.011s	sys 0.013s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10569,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:04.450358 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=3.181125
I20260812 06:17:04.542599 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.092s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6935,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.543736 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=7.149875
I20260812 06:17:04.646037 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.102s	user 0.009s	sys 0.012s Metrics: {"bytes_written":8492251,"delete_count":0,"lbm_write_time_us":9237,"lbm_writes_lt_1ms":210,"reinsert_count":0,"update_count":1035}
I20260812 06:17:04.646636 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:04.750806 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.104s	user 0.023s	sys 0.008s Metrics: {"bytes_written":11610079,"delete_count":0,"lbm_write_time_us":14545,"lbm_writes_lt_1ms":286,"reinsert_count":0,"update_count":1415}
I20260812 06:17:04.751351 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=7.149875
I20260812 06:17:04.860306 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.109s	user 0.008s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8121,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:04.860960 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:04.956904 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.096s	user 0.025s	sys 0.017s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":17765,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:17:04.957629 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=3.181125
I20260812 06:17:05.057996 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.100s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4635978,"delete_count":0,"lbm_write_time_us":5120,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:17:05.058733 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=10.126437
I20260812 06:17:05.161036 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.102s	user 0.027s	sys 0.013s Metrics: {"bytes_written":11774183,"delete_count":0,"lbm_write_time_us":16699,"lbm_writes_lt_1ms":290,"reinsert_count":0,"update_count":1435}
I20260812 06:17:05.161737 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=6.157687
I20260812 06:17:05.229995 24578 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.847s	user 1.832s	sys 0.120s
I20260812 06:17:05.256757 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.095s	user 0.003s	sys 0.017s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":8779,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.257648 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4): perf score=6.157687
I20260812 06:17:05.360750 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushDeltaMemStoresOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.103s	user 0.018s	sys 0.003s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9093,"lbm_writes_lt_1ms":203,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":1000}
I20260812 06:17:05.361537 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling FlushMRSOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:05.462509 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: FlushMRSOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.101s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1357578,"cfile_init":1,"dirs.queue_time_us":260,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1895,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33,"thread_start_us":110,"threads_started":1}
I20260812 06:17:05.463673 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling LogGCOp(35a401734fd34191b1263070d9008eb4): free 121006708 bytes of WAL
I20260812 06:17:05.464001 25031 log_reader.cc:385] T 35a401734fd34191b1263070d9008eb4: removed 12 log segments from log reader
I20260812 06:17:05.464061 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000029 (ops 137-141)
I20260812 06:17:05.464112 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000030 (ops 142-146)
I20260812 06:17:05.464155 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000031 (ops 147-151)
I20260812 06:17:05.464246 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000032 (ops 152-156)
I20260812 06:17:05.464311 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000033 (ops 157-161)
I20260812 06:17:05.464365 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000034 (ops 162-166)
I20260812 06:17:05.464414 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000035 (ops 167-170)
I20260812 06:17:05.464464 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000036 (ops 171-175)
I20260812 06:17:05.464542 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000037 (ops 176-180)
I20260812 06:17:05.464607 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000038 (ops 181-185)
I20260812 06:17:05.464818 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000039 (ops 186-190)
I20260812 06:17:05.464883 25031 log.cc:1079] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: Deleting log segment in path: /tmp/dist-test-taskDO_Ghi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515414470232-24578-0/minicluster-data/ts-0-root/wals/35a401734fd34191b1263070d9008eb4/wal-000000040 (ops 191-195)
I20260812 06:17:05.490310 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: LogGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.026s	user 0.006s	sys 0.019s Metrics: {}
I20260812 06:17:05.490727 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4): 507 bytes on disk
I20260812 06:17:05.491168 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: UndoDeltaBlockGCOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.491696 25122 maintenance_manager.cc:419] P 26818799499147a1bbd97625d08c4dbd: Scheduling MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4): perf score=1.000000
I20260812 06:17:05.535138 24578 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.305s	user 0.001s	sys 0.000s
I20260812 06:17:05.535699 24578 tablet_server.cc:179] TabletServer@127.24.0.129:0 shutting down...
I20260812 06:17:07.073742 25031 maintenance_manager.cc:643] P 26818799499147a1bbd97625d08c4dbd: MajorDeltaCompactionOp(35a401734fd34191b1263070d9008eb4) complete. Timing: real 1.582s	user 0.529s	sys 1.050s Metrics: {"cfile_cache_hit":2121,"cfile_cache_hit_bytes":90016391,"cfile_cache_miss":1021,"cfile_cache_miss_bytes":41422227,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":12,"delta_iterators_relevant":12,"dirs.queue_time_us":1011,"lbm_read_time_us":17075,"lbm_reads_lt_1ms":1037,"lbm_write_time_us":583522,"lbm_writes_1-10_ms":9,"lbm_writes_lt_1ms":3137,"peak_mem_usage":386206772,"reinsert_count":0,"thread_start_us":591,"threads_started":7,"update_count":15500,"wal-append.queue_time_us":248}
I20260812 06:17:07.074358 24578 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:07.074671 24578 tablet_replica.cc:333] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd: stopping tablet replica
I20260812 06:17:07.074856 24578 raft_consensus.cc:2243] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.075044 24578 raft_consensus.cc:2272] T 35a401734fd34191b1263070d9008eb4 P 26818799499147a1bbd97625d08c4dbd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.088573 24578 tablet_server.cc:196] TabletServer@127.24.0.129:0 shutdown complete.
I20260812 06:17:07.537016 24578 master.cc:562] Master@127.24.0.190:42283 shutting down...
I20260812 06:17:07.540961 24578 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.541141 24578 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.541193 24578 tablet_replica.cc:333] T 00000000000000000000000000000000 P b0764f77d25a43678442de51d658f170: stopping tablet replica
I20260812 06:17:07.553728 24578 master.cc:584] Master@127.24.0.190:42283 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (7477 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13167 ms total)

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