[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:19.147742 26429 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.207.126:34219
I20260812 06:17:19.148619 26429 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:19.149147 26429 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:19.154894 26443 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:19.154949 26429 server_base.cc:1061] running on GCE node
W20260812 06:17:19.154904 26437 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:19.155104 26445 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:19.155584 26429 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:19.155670 26429 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:19.155718 26429 hybrid_clock.cc:648] HybridClock initialized: now 1786515439155716 us; error 0 us; skew 500 ppm
I20260812 06:17:19.157233 26429 webserver.cc:533] Webserver started at http://127.25.207.126:46847/ using document root <none> and password file <none>
I20260812 06:17:19.157692 26429 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:19.157747 26429 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:19.157948 26429 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:19.159416 26429 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/master-0-root/instance:
uuid: "a4135bf6e14949cb97347e23acdc2704"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-bqcl"
I20260812 06:17:19.162456 26429 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:17:19.164249 26456 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:19.165104 26429 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:19.165197 26429 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/master-0-root
uuid: "a4135bf6e14949cb97347e23acdc2704"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-bqcl"
I20260812 06:17:19.165292 26429 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-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:19.183092 26429 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:19.183600 26429 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:19.183734 26429 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:19.190369 26429 rpc_server.cc:307] RPC server started. Bound to: 127.25.207.126:34219
I20260812 06:17:19.190403 26563 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.207.126:34219 every 8 connection(s)
I20260812 06:17:19.192306 26564 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:19.197274 26564 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: Bootstrap starting.
I20260812 06:17:19.199445 26564 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:19.200255 26564 log.cc:826] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:19.201704 26564 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: No bootstrap required, opened a new log
I20260812 06:17:19.204289 26564 raft_consensus.cc:359] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4135bf6e14949cb97347e23acdc2704" member_type: VOTER }
I20260812 06:17:19.204447 26564 raft_consensus.cc:385] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:19.204523 26564 raft_consensus.cc:740] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4135bf6e14949cb97347e23acdc2704, State: Initialized, Role: FOLLOWER
I20260812 06:17:19.205076 26564 consensus_queue.cc:260] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [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: "a4135bf6e14949cb97347e23acdc2704" member_type: VOTER }
I20260812 06:17:19.205243 26564 raft_consensus.cc:399] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:19.205310 26564 raft_consensus.cc:493] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:19.205425 26564 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:19.206106 26564 raft_consensus.cc:515] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4135bf6e14949cb97347e23acdc2704" member_type: VOTER }
I20260812 06:17:19.206506 26564 leader_election.cc:304] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [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: a4135bf6e14949cb97347e23acdc2704; no voters: 
I20260812 06:17:19.206794 26564 leader_election.cc:290] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:19.206892 26572 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:19.207108 26572 raft_consensus.cc:697] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 1 LEADER]: Becoming Leader. State: Replica: a4135bf6e14949cb97347e23acdc2704, State: Running, Role: LEADER
I20260812 06:17:19.207460 26572 consensus_queue.cc:237] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [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: "a4135bf6e14949cb97347e23acdc2704" member_type: VOTER }
I20260812 06:17:19.207661 26564 sys_catalog.cc:565] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:19.208976 26575 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a4135bf6e14949cb97347e23acdc2704" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4135bf6e14949cb97347e23acdc2704" member_type: VOTER } }
I20260812 06:17:19.209105 26575 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:19.209400 26576 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a4135bf6e14949cb97347e23acdc2704. Latest consensus state: current_term: 1 leader_uuid: "a4135bf6e14949cb97347e23acdc2704" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4135bf6e14949cb97347e23acdc2704" member_type: VOTER } }
I20260812 06:17:19.209470 26576 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:19.209623 26429 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:19.211309 26613 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:19.211372 26613 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:19.211455 26602 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:19.212141 26602 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:19.216243 26602 catalog_manager.cc:1383] Generated new cluster ID: ea4a2ca2ffe34f409bdb63dd9ada47c1
I20260812 06:17:19.216302 26602 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:19.224560 26602 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:19.225659 26602 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:19.231860 26602 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: Generated new TSK 0
I20260812 06:17:19.232362 26602 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:19.241905 26429 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:19.244210 26619 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:19.244275 26617 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:19.244366 26621 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:19.244560 26429 server_base.cc:1061] running on GCE node
I20260812 06:17:19.244729 26429 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:19.244769 26429 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:19.244783 26429 hybrid_clock.cc:648] HybridClock initialized: now 1786515439244783 us; error 0 us; skew 500 ppm
I20260812 06:17:19.245595 26429 webserver.cc:533] Webserver started at http://127.25.207.65:36913/ using document root <none> and password file <none>
I20260812 06:17:19.245741 26429 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:19.245791 26429 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:19.245863 26429 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:19.246254 26429 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/instance:
uuid: "dfd1c8e562564a3084563a9bbb60e9f3"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-bqcl"
I20260812 06:17:19.247605 26429 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:19.248535 26630 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:19.248785 26429 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:19.248852 26429 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root
uuid: "dfd1c8e562564a3084563a9bbb60e9f3"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-bqcl"
I20260812 06:17:19.248914 26429 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-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:19.267015 26429 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:19.267365 26429 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:19.267767 26429 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:19.268532 26429 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:19.268581 26429 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.268643 26429 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:19.268668 26429 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.274777 26429 rpc_server.cc:307] RPC server started. Bound to: 127.25.207.65:39799
I20260812 06:17:19.274824 26751 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.207.65:39799 every 8 connection(s)
I20260812 06:17:19.283623 26753 heartbeater.cc:344] Connected to a master server at 127.25.207.126:34219
I20260812 06:17:19.283824 26753 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:19.284206 26753 heartbeater.cc:507] Master 127.25.207.126:34219 requested a full tablet report, sending...
I20260812 06:17:19.285522 26502 ts_manager.cc:194] Registered new tserver with Master: dfd1c8e562564a3084563a9bbb60e9f3 (127.25.207.65:39799)
I20260812 06:17:19.285682 26429 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010334859s
I20260812 06:17:19.286985 26502 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40880
I20260812 06:17:19.294206 26502 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40886:
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:19.306546 26679 tablet_service.cc:1511] Processing CreateTablet for tablet e426c62b42334e38b4ecbaab5548c9c8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ec81f819cc614670a5439e504b87a6e1]), partition=
I20260812 06:17:19.306986 26679 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e426c62b42334e38b4ecbaab5548c9c8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:19.309659 26771 tablet_bootstrap.cc:492] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Bootstrap starting.
I20260812 06:17:19.310600 26771 tablet_bootstrap.cc:654] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:19.311571 26771 tablet_bootstrap.cc:492] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: No bootstrap required, opened a new log
I20260812 06:17:19.311650 26771 ts_tablet_manager.cc:1403] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:19.312031 26771 raft_consensus.cc:359] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfd1c8e562564a3084563a9bbb60e9f3" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39799 } }
I20260812 06:17:19.312120 26771 raft_consensus.cc:385] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:19.312155 26771 raft_consensus.cc:740] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dfd1c8e562564a3084563a9bbb60e9f3, State: Initialized, Role: FOLLOWER
I20260812 06:17:19.312278 26771 consensus_queue.cc:260] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [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: "dfd1c8e562564a3084563a9bbb60e9f3" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39799 } }
I20260812 06:17:19.312354 26771 raft_consensus.cc:399] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:19.312390 26771 raft_consensus.cc:493] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:19.312438 26771 raft_consensus.cc:3060] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:19.313143 26771 raft_consensus.cc:515] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfd1c8e562564a3084563a9bbb60e9f3" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39799 } }
I20260812 06:17:19.313256 26771 leader_election.cc:304] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [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: dfd1c8e562564a3084563a9bbb60e9f3; no voters: 
I20260812 06:17:19.313438 26771 leader_election.cc:290] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:19.313542 26775 raft_consensus.cc:2804] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:19.313717 26775 raft_consensus.cc:697] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 1 LEADER]: Becoming Leader. State: Replica: dfd1c8e562564a3084563a9bbb60e9f3, State: Running, Role: LEADER
I20260812 06:17:19.313752 26771 ts_tablet_manager.cc:1434] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:19.314275 26775 consensus_queue.cc:237] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [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: "dfd1c8e562564a3084563a9bbb60e9f3" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39799 } }
I20260812 06:17:19.314064 26753 heartbeater.cc:499] Master 127.25.207.126:34219 was elected leader, sending a full tablet report...
I20260812 06:17:19.316627 26502 catalog_manager.cc:5719] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 reported cstate change: term changed from 0 to 1, leader changed from <none> to dfd1c8e562564a3084563a9bbb60e9f3 (127.25.207.65). New cstate: current_term: 1 leader_uuid: "dfd1c8e562564a3084563a9bbb60e9f3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfd1c8e562564a3084563a9bbb60e9f3" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39799 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:19.377134 26429 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.026s	sys 0.000s
I20260812 06:17:19.525825 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=19.054940
I20260812 06:17:19.674336 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.148s	user 0.135s	sys 0.012s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":204,"delete_count":0,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":764,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37011,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":110,"threads_started":1,"update_count":1450}
I20260812 06:17:19.675515 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling LogGCOp(e426c62b42334e38b4ecbaab5548c9c8): free 20743880 bytes of WAL
I20260812 06:17:19.675822 26638 log_reader.cc:385] T e426c62b42334e38b4ecbaab5548c9c8: removed 2 log segments from log reader
I20260812 06:17:19.675900 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000001 (ops 1-6)
I20260812 06:17:19.675956 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000002 (ops 7-11)
I20260812 06:17:19.681723 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: LogGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:19.682269 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:19.714586 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.032s	user 0.010s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.715040 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:19.729112 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5489,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.729516 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8): 16821646 bytes on disk
I20260812 06:17:19.730163 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8) 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:19.730563 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:19.890200 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.159s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405562,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":506,"lbm_read_time_us":12430,"lbm_reads_lt_1ms":559,"lbm_write_time_us":25841,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":298,"threads_started":5,"update_count":2450}
I20260812 06:17:19.890885 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=10.126437
I20260812 06:17:19.930703 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.039s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13975,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.931093 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:19.941018 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.941419 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:20.058272 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.117s	user 0.080s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":9269,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21592,"lbm_writes_lt_1ms":443,"mutex_wait_us":252,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:17:20.058740 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=10.126437
I20260812 06:17:20.098812 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.040s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12143,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.099324 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:20.114328 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.114743 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:20.227221 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.112s	user 0.088s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1133,"lbm_read_time_us":7595,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20124,"lbm_writes_lt_1ms":443,"mutex_wait_us":406,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:20.227687 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=10.126437
I20260812 06:17:20.261530 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.034s	user 0.026s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12698,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.261946 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:20.271845 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.272281 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:20.389942 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.118s	user 0.092s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":282,"lbm_read_time_us":8381,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21118,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.390470 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=10.126437
I20260812 06:17:20.425384 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.035s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11459,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.425825 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:20.435652 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.436066 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:20.579644 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.143s	user 0.112s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":126,"lbm_read_time_us":10146,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22160,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:17:20.580130 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=10.126437
I20260812 06:17:20.623652 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.043s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14451,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.624126 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:20.633625 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.634075 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:20.750687 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.116s	user 0.096s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":7701,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22978,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:17:20.751138 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=10.126437
I20260812 06:17:20.795418 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.044s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14242,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.795964 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:20.810932 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.811410 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:20.837404 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1198,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1311,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:20.838227 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling LogGCOp(e426c62b42334e38b4ecbaab5548c9c8): free 112239257 bytes of WAL
I20260812 06:17:20.838442 26638 log_reader.cc:385] T e426c62b42334e38b4ecbaab5548c9c8: removed 11 log segments from log reader
I20260812 06:17:20.838495 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000003 (ops 12-16)
I20260812 06:17:20.838560 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000004 (ops 17-21)
I20260812 06:17:20.838595 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000005 (ops 22-26)
I20260812 06:17:20.838626 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000006 (ops 27-30)
I20260812 06:17:20.838657 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000007 (ops 31-35)
I20260812 06:17:20.838688 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000008 (ops 36-40)
I20260812 06:17:20.838718 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000009 (ops 41-45)
I20260812 06:17:20.838749 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000010 (ops 46-50)
I20260812 06:17:20.838783 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000011 (ops 51-55)
I20260812 06:17:20.838809 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000012 (ops 56-60)
I20260812 06:17:20.838831 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000013 (ops 61-65)
I20260812 06:17:20.860687 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: LogGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:20.861065 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=3.181125
I20260812 06:17:20.881660 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.020s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5790,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.882042 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:20.890798 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3285,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.891140 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8): 447 bytes on disk
I20260812 06:17:20.891490 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.891897 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:21.046597 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.155s	user 0.100s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1147,"lbm_read_time_us":9928,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28922,"lbm_writes_lt_1ms":643,"mutex_wait_us":866,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:21.047047 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:21.092795 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.046s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.093294 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:21.104264 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.104784 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:21.249271 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.144s	user 0.117s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":8451,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25281,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:17:21.249763 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:21.292518 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.043s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18049,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.292976 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:21.435127 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.142s	user 0.093s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":85,"lbm_read_time_us":10051,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22247,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:21.435762 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:21.480317 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.044s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18479,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.480739 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:21.491099 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.491633 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:21.659812 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.168s	user 0.110s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":501,"lbm_read_time_us":9631,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25414,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34688,"update_count":2500}
I20260812 06:17:21.660377 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:21.707617 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.047s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18340,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.708105 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:21.718314 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.718896 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:21.856006 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.137s	user 0.105s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":9180,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26692,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:21.859933 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=11.118625
I20260812 06:17:21.887276 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.027s	user 0.017s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":10731,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:21.887820 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:21.911448 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5415,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.911916 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:21.921316 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.921768 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:22.050956 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.129s	user 0.108s	sys 0.015s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":543,"lbm_read_time_us":8455,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24459,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.051544 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=11.118625
I20260812 06:17:22.089880 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.038s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14491,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:22.090459 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:22.112106 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.112586 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:22.122056 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.122478 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:22.153103 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1055,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2028,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:22.153764 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling LogGCOp(e426c62b42334e38b4ecbaab5548c9c8): free 133024419 bytes of WAL
I20260812 06:17:22.153975 26638 log_reader.cc:385] T e426c62b42334e38b4ecbaab5548c9c8: removed 13 log segments from log reader
I20260812 06:17:22.154029 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000014 (ops 66-70)
I20260812 06:17:22.154060 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000015 (ops 71-74)
I20260812 06:17:22.154094 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000016 (ops 75-79)
I20260812 06:17:22.154140 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000017 (ops 80-84)
I20260812 06:17:22.154175 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000018 (ops 85-89)
I20260812 06:17:22.154208 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000019 (ops 90-94)
I20260812 06:17:22.154242 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000020 (ops 95-99)
I20260812 06:17:22.154274 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000021 (ops 100-104)
I20260812 06:17:22.154307 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000022 (ops 105-109)
I20260812 06:17:22.154337 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000023 (ops 110-114)
I20260812 06:17:22.154369 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000024 (ops 115-119)
I20260812 06:17:22.154400 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000025 (ops 120-124)
I20260812 06:17:22.154433 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000026 (ops 125-129)
I20260812 06:17:22.175455 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: LogGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.022s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:17:22.175946 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:22.194052 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4184708,"delete_count":0,"lbm_write_time_us":6383,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:17:22.194659 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:22.204034 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":3671,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:22.204409 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:22.406487 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.202s	user 0.131s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020854,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":342,"lbm_read_time_us":12855,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33011,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:17:22.407140 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8): 482 bytes on disk
I20260812 06:17:22.407617 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.408342 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=15.087375
I20260812 06:17:22.467173 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.059s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16984243,"delete_count":0,"lbm_write_time_us":17624,"lbm_writes_lt_1ms":417,"reinsert_count":0,"update_count":2070}
I20260812 06:17:22.467643 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=6.157687
I20260812 06:17:22.486822 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":7630744,"delete_count":0,"lbm_write_time_us":7837,"lbm_writes_lt_1ms":189,"reinsert_count":0,"update_count":930}
I20260812 06:17:22.487298 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:22.669380 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.182s	user 0.127s	sys 0.051s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":71,"lbm_read_time_us":12011,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32474,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:22.674476 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=15.087375
I20260812 06:17:22.729761 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.052s	user 0.019s	sys 0.029s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22835,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:22.730319 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:22.752846 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.022s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.753249 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:22.762602 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.762989 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:22.954757 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.192s	user 0.132s	sys 0.059s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":78,"lbm_read_time_us":12981,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35024,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:17:22.955364 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:22.998787 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.039s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17549,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.999248 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:23.015180 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.015622 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:23.175017 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.159s	user 0.097s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":501,"lbm_read_time_us":10953,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27101,"lbm_writes_lt_1ms":543,"mutex_wait_us":231,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:17:23.175541 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:23.228438 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.053s	user 0.020s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24033,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.228984 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:23.239180 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.239705 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:23.394150 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.154s	user 0.110s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":10404,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25032,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":597760,"update_count":2500}
I20260812 06:17:23.394778 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=14.095187
I20260812 06:17:23.448958 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.054s	user 0.015s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20477,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.449523 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:23.464273 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.464751 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:23.507855 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushMRSOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.043s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1241,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1391,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:23.508745 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling LogGCOp(e426c62b42334e38b4ecbaab5548c9c8): free 124710577 bytes of WAL
I20260812 06:17:23.508986 26638 log_reader.cc:385] T e426c62b42334e38b4ecbaab5548c9c8: removed 12 log segments from log reader
I20260812 06:17:23.509045 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000027 (ops 130-134)
I20260812 06:17:23.509091 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000028 (ops 135-139)
I20260812 06:17:23.509131 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000029 (ops 140-144)
I20260812 06:17:23.509169 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000030 (ops 145-149)
I20260812 06:17:23.509205 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000031 (ops 150-154)
I20260812 06:17:23.509243 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000032 (ops 155-159)
I20260812 06:17:23.509279 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000033 (ops 160-164)
I20260812 06:17:23.509315 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000034 (ops 165-169)
I20260812 06:17:23.509352 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000035 (ops 170-174)
I20260812 06:17:23.509389 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000036 (ops 175-179)
I20260812 06:17:23.509426 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000037 (ops 180-184)
I20260812 06:17:23.509462 26638 log.cc:1079] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/e426c62b42334e38b4ecbaab5548c9c8/wal-000000038 (ops 185-189)
I20260812 06:17:23.532963 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: LogGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:23.533384 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8): 465 bytes on disk
I20260812 06:17:23.533964 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: UndoDeltaBlockGCOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:17:23.534552 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:23.553462 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.019s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.553845 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=2.188937
I20260812 06:17:23.563606 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.564009 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=1.000000
I20260812 06:17:23.765312 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: MajorDeltaCompactionOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.201s	user 0.130s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020746,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":473,"lbm_read_time_us":13709,"lbm_reads_lt_1ms":774,"lbm_write_time_us":34229,"lbm_writes_lt_1ms":743,"mutex_wait_us":1850,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:17:23.765900 26757 maintenance_manager.cc:419] P dfd1c8e562564a3084563a9bbb60e9f3: Scheduling FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8): perf score=15.087375
I20260812 06:17:23.782753 26429 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.406s	user 1.652s	sys 0.100s
I20260812 06:17:23.827637 26429 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.044s	user 0.002s	sys 0.000s
I20260812 06:17:23.828195 26429 tablet_server.cc:179] TabletServer@127.25.207.65:0 shutting down...
I20260812 06:17:23.835646 26638 maintenance_manager.cc:643] P dfd1c8e562564a3084563a9bbb60e9f3: FlushDeltaMemStoresOp(e426c62b42334e38b4ecbaab5548c9c8) complete. Timing: real 0.069s	user 0.019s	sys 0.042s Metrics: {"bytes_written":16820149,"delete_count":0,"lbm_write_time_us":30397,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:17:23.836102 26429 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:23.836449 26429 tablet_replica.cc:333] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3: stopping tablet replica
I20260812 06:17:23.836664 26429 raft_consensus.cc:2243] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:23.836861 26429 raft_consensus.cc:2272] T e426c62b42334e38b4ecbaab5548c9c8 P dfd1c8e562564a3084563a9bbb60e9f3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:23.851485 26429 tablet_server.cc:196] TabletServer@127.25.207.65:0 shutdown complete.
I20260812 06:17:23.855702 26429 master.cc:562] Master@127.25.207.126:34219 shutting down...
I20260812 06:17:23.858960 26429 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:23.859107 26429 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:23.859185 26429 tablet_replica.cc:333] T 00000000000000000000000000000000 P a4135bf6e14949cb97347e23acdc2704: stopping tablet replica
I20260812 06:17:23.871187 26429 master.cc:584] Master@127.25.207.126:34219 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4792 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:23.939900 26429 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.207.126:40085
I20260812 06:17:23.940302 26429 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.942183 26818 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:23.942276 26817 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:23.942351 26429 server_base.cc:1061] running on GCE node
W20260812 06:17:23.942529 26823 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:23.942708 26429 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.942754 26429 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:23.942773 26429 hybrid_clock.cc:648] HybridClock initialized: now 1786515443942773 us; error 0 us; skew 500 ppm
I20260812 06:17:23.943547 26429 webserver.cc:533] Webserver started at http://127.25.207.126:38991/ using document root <none> and password file <none>
I20260812 06:17:23.943689 26429 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.943737 26429 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.943807 26429 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.944159 26429 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/master-0-root/instance:
uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-bqcl"
I20260812 06:17:23.945556 26429 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:23.946525 26829 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:23.946734 26429 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:23.946802 26429 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/master-0-root
uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-bqcl"
I20260812 06:17:23.946866 26429 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-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:23.971925 26429 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:23.972234 26429 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:23.975937 26429 rpc_server.cc:307] RPC server started. Bound to: 127.25.207.126:40085
I20260812 06:17:23.988293 26921 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.207.126:40085 every 8 connection(s)
I20260812 06:17:23.988859 26923 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:23.990741 26923 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f: Bootstrap starting.
I20260812 06:17:23.991525 26923 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:23.992522 26923 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f: No bootstrap required, opened a new log
I20260812 06:17:23.992923 26923 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f" member_type: VOTER }
I20260812 06:17:23.993026 26923 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:23.993057 26923 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1d0b3a8112fe4f9c8b34b8d319e00e7f, State: Initialized, Role: FOLLOWER
I20260812 06:17:23.993204 26923 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [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: "1d0b3a8112fe4f9c8b34b8d319e00e7f" member_type: VOTER }
I20260812 06:17:23.993285 26923 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:23.993328 26923 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:23.993386 26923 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:23.994055 26923 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f" member_type: VOTER }
I20260812 06:17:23.994220 26923 leader_election.cc:304] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [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: 1d0b3a8112fe4f9c8b34b8d319e00e7f; no voters: 
I20260812 06:17:23.994396 26923 leader_election.cc:290] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:23.994501 26931 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:23.994688 26931 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 1 LEADER]: Becoming Leader. State: Replica: 1d0b3a8112fe4f9c8b34b8d319e00e7f, State: Running, Role: LEADER
I20260812 06:17:23.994819 26931 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [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: "1d0b3a8112fe4f9c8b34b8d319e00e7f" member_type: VOTER }
I20260812 06:17:23.994885 26923 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:23.995229 26933 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f" member_type: VOTER } }
I20260812 06:17:23.995249 26935 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1d0b3a8112fe4f9c8b34b8d319e00e7f. Latest consensus state: current_term: 1 leader_uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0b3a8112fe4f9c8b34b8d319e00e7f" member_type: VOTER } }
I20260812 06:17:23.995400 26935 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:23.995594 26933 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:23.995970 26938 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:23.996608 26938 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:23.996843 26429 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:23.998365 26938 catalog_manager.cc:1383] Generated new cluster ID: ec719dad91964e0d8106414fd4ffea34
I20260812 06:17:23.998423 26938 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:24.019364 26938 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:24.019856 26938 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:24.025614 26938 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f: Generated new TSK 0
I20260812 06:17:24.025754 26938 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:24.028995 26429 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.030835 26970 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:24.030905 26966 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.030979 26429 server_base.cc:1061] running on GCE node
W20260812 06:17:24.031059 26964 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:24.031258 26429 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.031302 26429 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:24.031316 26429 hybrid_clock.cc:648] HybridClock initialized: now 1786515444031316 us; error 0 us; skew 500 ppm
I20260812 06:17:24.032069 26429 webserver.cc:533] Webserver started at http://127.25.207.65:36233/ using document root <none> and password file <none>
I20260812 06:17:24.032204 26429 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.032254 26429 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.032323 26429 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.032675 26429 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/instance:
uuid: "d84f018b4ad346d8bf7f28238be6f85d"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-bqcl"
I20260812 06:17:24.034022 26429 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:24.034883 26980 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:24.035084 26429 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:24.035145 26429 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root
uuid: "d84f018b4ad346d8bf7f28238be6f85d"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-bqcl"
I20260812 06:17:24.035208 26429 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-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:24.044312 26429 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.044579 26429 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.044812 26429 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:24.045202 26429 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:24.045249 26429 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.045282 26429 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:24.045310 26429 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.049188 26429 rpc_server.cc:307] RPC server started. Bound to: 127.25.207.65:39507
I20260812 06:17:24.049213 27103 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.207.65:39507 every 8 connection(s)
I20260812 06:17:24.057471 27105 heartbeater.cc:344] Connected to a master server at 127.25.207.126:40085
I20260812 06:17:24.057580 27105 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:24.057766 27105 heartbeater.cc:507] Master 127.25.207.126:40085 requested a full tablet report, sending...
I20260812 06:17:24.058342 26852 ts_manager.cc:194] Registered new tserver with Master: d84f018b4ad346d8bf7f28238be6f85d (127.25.207.65:39507)
I20260812 06:17:24.058996 26852 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60028
I20260812 06:17:24.059350 26429 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009797115s
I20260812 06:17:24.065362 26852 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60044:
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:24.073055 27035 tablet_service.cc:1511] Processing CreateTablet for tablet 256e3c350cd54726bac9fec967adbda6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e03411e9a9d34c7ba6a7884accb9b533]), partition=
I20260812 06:17:24.073282 27035 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 256e3c350cd54726bac9fec967adbda6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.075069 27124 tablet_bootstrap.cc:492] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Bootstrap starting.
I20260812 06:17:24.075871 27124 tablet_bootstrap.cc:654] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.076817 27124 tablet_bootstrap.cc:492] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: No bootstrap required, opened a new log
I20260812 06:17:24.076886 27124 ts_tablet_manager.cc:1403] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:24.077239 27124 raft_consensus.cc:359] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d84f018b4ad346d8bf7f28238be6f85d" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39507 } }
I20260812 06:17:24.077319 27124 raft_consensus.cc:385] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.077340 27124 raft_consensus.cc:740] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d84f018b4ad346d8bf7f28238be6f85d, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.077461 27124 consensus_queue.cc:260] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [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: "d84f018b4ad346d8bf7f28238be6f85d" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39507 } }
I20260812 06:17:24.077545 27124 raft_consensus.cc:399] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.077585 27124 raft_consensus.cc:493] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.077634 27124 raft_consensus.cc:3060] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.078384 27124 raft_consensus.cc:515] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d84f018b4ad346d8bf7f28238be6f85d" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39507 } }
I20260812 06:17:24.078508 27124 leader_election.cc:304] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [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: d84f018b4ad346d8bf7f28238be6f85d; no voters: 
I20260812 06:17:24.078679 27124 leader_election.cc:290] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.078764 27126 raft_consensus.cc:2804] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.078960 27126 raft_consensus.cc:697] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 1 LEADER]: Becoming Leader. State: Replica: d84f018b4ad346d8bf7f28238be6f85d, State: Running, Role: LEADER
I20260812 06:17:24.079037 27105 heartbeater.cc:499] Master 127.25.207.126:40085 was elected leader, sending a full tablet report...
I20260812 06:17:24.079110 27126 consensus_queue.cc:237] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [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: "d84f018b4ad346d8bf7f28238be6f85d" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39507 } }
I20260812 06:17:24.079216 27124 ts_tablet_manager.cc:1434] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:24.080243 26852 catalog_manager.cc:5719] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d reported cstate change: term changed from 0 to 1, leader changed from <none> to d84f018b4ad346d8bf7f28238be6f85d (127.25.207.65). New cstate: current_term: 1 leader_uuid: "d84f018b4ad346d8bf7f28238be6f85d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d84f018b4ad346d8bf7f28238be6f85d" member_type: VOTER last_known_addr { host: "127.25.207.65" port: 39507 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:24.133441 26429 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.009s	sys 0.012s
I20260812 06:17:24.300199 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushMRSOp(256e3c350cd54726bac9fec967adbda6): perf score=23.023690
I20260812 06:17:24.460608 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushMRSOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.160s	user 0.114s	sys 0.043s Metrics: {"bytes_written":13497195,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":910,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42568,"lbm_writes_lt_1ms":886,"mutex_wait_us":193,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1645}
I20260812 06:17:24.461225 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling LogGCOp(256e3c350cd54726bac9fec967adbda6): free 20743880 bytes of WAL
I20260812 06:17:24.461477 26986 log_reader.cc:385] T 256e3c350cd54726bac9fec967adbda6: removed 2 log segments from log reader
I20260812 06:17:24.461546 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000001 (ops 1-6)
I20260812 06:17:24.461645 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000002 (ops 7-11)
I20260812 06:17:24.466763 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: LogGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:24.467079 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6): 20513813 bytes on disk
I20260812 06:17:24.467464 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.467870 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:24.478106 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.010s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102663,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.478459 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=1.196750
I20260812 06:17:24.486032 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":2785,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:17:24.486382 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:24.637410 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.151s	user 0.103s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815783,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":441,"lbm_read_time_us":11899,"lbm_reads_lt_1ms":569,"lbm_write_time_us":25864,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":316,"threads_started":5,"update_count":2500}
I20260812 06:17:24.637859 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:24.684538 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.045s	user 0.013s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":15822,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.685065 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:24.694837 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.695475 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:24.845317 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.150s	user 0.098s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1180,"lbm_read_time_us":11231,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25661,"lbm_writes_lt_1ms":543,"mutex_wait_us":525,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:17:24.845969 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=12.110812
I20260812 06:17:24.881407 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":13989481,"delete_count":0,"lbm_write_time_us":15960,"lbm_writes_lt_1ms":344,"reinsert_count":0,"update_count":1705}
I20260812 06:17:24.881855 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=1.196750
I20260812 06:17:24.901774 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.020s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2830884,"delete_count":0,"lbm_write_time_us":3497,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:17:24.902307 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:24.914961 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4929,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.915350 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:25.072240 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.157s	user 0.089s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815765,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":218,"lbm_read_time_us":11340,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25185,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:17:25.072885 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:25.131788 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.059s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.132263 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:25.142186 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.142550 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:25.306071 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.163s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":11744,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24652,"lbm_writes_lt_1ms":543,"mutex_wait_us":263,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:25.306669 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:25.365401 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.059s	user 0.024s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23835,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.365937 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:25.379844 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.380237 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:25.551759 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.171s	user 0.102s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":560,"lbm_read_time_us":11648,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25468,"lbm_writes_lt_1ms":543,"mutex_wait_us":252,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26624,"update_count":2500}
I20260812 06:17:25.552276 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:25.606459 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.054s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.606941 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:25.616605 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.616961 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushMRSOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:25.655778 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushMRSOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.039s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1241,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1364,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:25.656363 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling LogGCOp(256e3c350cd54726bac9fec967adbda6): free 120553391 bytes of WAL
I20260812 06:17:25.656586 26986 log_reader.cc:385] T 256e3c350cd54726bac9fec967adbda6: removed 12 log segments from log reader
I20260812 06:17:25.656634 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000003 (ops 12-16)
I20260812 06:17:25.656663 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000004 (ops 17-20)
I20260812 06:17:25.656697 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000005 (ops 21-25)
I20260812 06:17:25.656726 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000006 (ops 26-30)
I20260812 06:17:25.656759 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000007 (ops 31-35)
I20260812 06:17:25.656792 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000008 (ops 36-40)
I20260812 06:17:25.656826 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000009 (ops 41-45)
I20260812 06:17:25.656857 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000010 (ops 46-50)
I20260812 06:17:25.656889 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000011 (ops 51-54)
I20260812 06:17:25.656921 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000012 (ops 55-59)
I20260812 06:17:25.656952 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000013 (ops 60-64)
I20260812 06:17:25.656983 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000014 (ops 65-69)
I20260812 06:17:25.676589 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: LogGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.020s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:25.676985 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:25.697153 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.020s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.697562 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6): 472 bytes on disk
I20260812 06:17:25.697926 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.698403 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:25.712713 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.014s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.713191 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:25.935770 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.222s	user 0.150s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":731,"lbm_read_time_us":13832,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36603,"lbm_writes_lt_1ms":743,"mutex_wait_us":465,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:17:25.936304 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=18.063937
I20260812 06:17:25.992112 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.056s	user 0.035s	sys 0.012s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":22021,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:25.992563 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:26.002660 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.003031 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:26.286851 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.284s	user 0.212s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":15320,"lbm_reads_lt_1ms":672,"lbm_write_time_us":59924,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:26.290411 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:26.368777 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.077s	user 0.042s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":35091,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.369391 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:26.398847 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.029s	user 0.021s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.399724 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:26.678571 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.279s	user 0.217s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1290,"lbm_read_time_us":17340,"lbm_reads_lt_1ms":572,"lbm_write_time_us":52741,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:17:26.679654 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=11.118625
I20260812 06:17:26.732335 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.052s	user 0.018s	sys 0.032s Metrics: {"bytes_written":13086951,"delete_count":0,"lbm_write_time_us":22643,"lbm_writes_lt_1ms":322,"reinsert_count":0,"update_count":1595}
I20260812 06:17:26.733536 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:26.753597 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":6201,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:26.754554 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:27.025410 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.271s	user 0.202s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713254,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":20138,"lbm_reads_lt_1ms":468,"lbm_write_time_us":44294,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:17:27.026496 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=11.118625
I20260812 06:17:27.106338 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.080s	user 0.042s	sys 0.033s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":30577,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:27.107061 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:27.148685 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.041s	user 0.013s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.150194 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:27.196874 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.046s	user 0.025s	sys 0.021s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":10263,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.198092 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:27.645448 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.447s	user 0.299s	sys 0.144s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":651,"lbm_read_time_us":46878,"lbm_reads_lt_1ms":573,"lbm_write_time_us":72178,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":363,"threads_started":6,"update_count":2500}
I20260812 06:17:27.645985 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:27.692402 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.046s	user 0.036s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18719,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.692989 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:27.703893 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.704298 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:27.881875 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.177s	user 0.115s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":897,"lbm_read_time_us":9579,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31436,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:17:27.882432 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=14.095187
I20260812 06:17:27.928738 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.046s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20321,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.929257 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:27.940706 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.941222 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushMRSOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:27.974699 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushMRSOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":1146,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1576,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:27.975306 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling LogGCOp(256e3c350cd54726bac9fec967adbda6): free 140885420 bytes of WAL
I20260812 06:17:27.975522 26986 log_reader.cc:385] T 256e3c350cd54726bac9fec967adbda6: removed 14 log segments from log reader
I20260812 06:17:27.975570 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000015 (ops 70-74)
I20260812 06:17:27.975600 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000016 (ops 75-78)
I20260812 06:17:27.975633 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000017 (ops 79-83)
I20260812 06:17:27.975657 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000018 (ops 84-88)
I20260812 06:17:27.975688 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000019 (ops 89-92)
I20260812 06:17:27.975721 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000020 (ops 93-97)
I20260812 06:17:27.975755 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000021 (ops 98-102)
I20260812 06:17:27.975786 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000022 (ops 103-107)
I20260812 06:17:27.975819 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000023 (ops 108-112)
I20260812 06:17:27.975850 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000024 (ops 113-117)
I20260812 06:17:27.975883 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000025 (ops 118-122)
I20260812 06:17:27.975914 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000026 (ops 123-126)
I20260812 06:17:27.975944 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000027 (ops 127-131)
I20260812 06:17:27.975977 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000028 (ops 132-136)
I20260812 06:17:27.998889 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: LogGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:27.999246 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6): 493 bytes on disk
I20260812 06:17:27.999724 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.000283 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=4.173312
I20260812 06:17:28.017300 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":6194894,"delete_count":0,"lbm_write_time_us":7305,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:17:28.017650 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:28.023392 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.006s	user 0.004s	sys 0.000s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":1885,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:17:28.023716 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:28.238391 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.215s	user 0.140s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":153,"lbm_read_time_us":15287,"lbm_reads_lt_1ms":774,"lbm_write_time_us":32491,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":26496,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:17:28.241885 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=17.071750
I20260812 06:17:28.300403 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.058s	user 0.032s	sys 0.011s Metrics: {"bytes_written":18748277,"delete_count":0,"lbm_write_time_us":20127,"lbm_writes_lt_1ms":460,"reinsert_count":0,"update_count":2285}
I20260812 06:17:28.300897 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=4.173312
I20260812 06:17:28.314898 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.014s	user 0.001s	sys 0.012s Metrics: {"bytes_written":5866711,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:17:28.315366 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:28.515724 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.200s	user 0.119s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":15250,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31038,"lbm_writes_lt_1ms":643,"mutex_wait_us":105,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:17:28.516309 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=18.063937
I20260812 06:17:28.582453 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.066s	user 0.028s	sys 0.028s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25714,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:28.582908 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:28.593468 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.594220 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:28.784175 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.190s	user 0.130s	sys 0.057s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":13303,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30245,"lbm_writes_lt_1ms":643,"mutex_wait_us":429,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":3000}
I20260812 06:17:28.784783 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=16.079562
I20260812 06:17:28.853336 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.068s	user 0.036s	sys 0.020s Metrics: {"bytes_written":17804726,"delete_count":0,"lbm_write_time_us":26791,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2170}
I20260812 06:17:28.853767 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=5.165500
I20260812 06:17:28.870484 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":6810264,"delete_count":0,"lbm_write_time_us":6991,"lbm_writes_lt_1ms":169,"reinsert_count":0,"update_count":830}
I20260812 06:17:28.870934 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:29.063308 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.191s	user 0.121s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":580,"lbm_read_time_us":12774,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31594,"lbm_writes_lt_1ms":643,"mutex_wait_us":344,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":3000}
I20260812 06:17:29.063925 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=18.063937
I20260812 06:17:29.127696 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.064s	user 0.025s	sys 0.029s Metrics: {"bytes_written":20512400,"delete_count":0,"lbm_write_time_us":25354,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.128153 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:29.139515 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.140166 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:29.336222 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.196s	user 0.131s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918182,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":579,"lbm_read_time_us":13490,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31662,"lbm_writes_lt_1ms":643,"mutex_wait_us":276,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31232,"update_count":3000}
I20260812 06:17:29.336869 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=18.063937
I20260812 06:17:29.398403 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.061s	user 0.032s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":21031,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.398910 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:29.413761 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.414284 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushMRSOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:29.442770 26429 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.309s	user 1.872s	sys 0.225s
I20260812 06:17:29.444648 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushMRSOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1180,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1722,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:29.445416 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling LogGCOp(256e3c350cd54726bac9fec967adbda6): free 133477725 bytes of WAL
I20260812 06:17:29.445659 26986 log_reader.cc:385] T 256e3c350cd54726bac9fec967adbda6: removed 13 log segments from log reader
I20260812 06:17:29.445710 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000029 (ops 137-141)
I20260812 06:17:29.445748 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000030 (ops 142-146)
I20260812 06:17:29.445781 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000031 (ops 147-151)
I20260812 06:17:29.445807 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000032 (ops 152-156)
I20260812 06:17:29.445838 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000033 (ops 157-161)
I20260812 06:17:29.445870 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000034 (ops 162-166)
I20260812 06:17:29.445900 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000035 (ops 167-171)
I20260812 06:17:29.445930 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000036 (ops 172-176)
I20260812 06:17:29.445961 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000037 (ops 177-181)
I20260812 06:17:29.445991 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000038 (ops 182-186)
I20260812 06:17:29.446019 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000039 (ops 187-191)
I20260812 06:17:29.446048 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000040 (ops 192-196)
I20260812 06:17:29.446079 26986 log.cc:1079] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: Deleting log segment in path: /tmp/dist-test-taskw8220g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439137843-26429-0/minicluster-data/ts-0-root/wals/256e3c350cd54726bac9fec967adbda6/wal-000000041 (ops 197-201)
I20260812 06:17:29.465934 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: LogGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.020s	user 0.002s	sys 0.015s Metrics: {}
I20260812 06:17:29.466476 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6): perf score=2.188937
I20260812 06:17:29.475831 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: FlushDeltaMemStoresOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.476305 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6): 492 bytes on disk
I20260812 06:17:29.476733 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: UndoDeltaBlockGCOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.477324 27106 maintenance_manager.cc:419] P d84f018b4ad346d8bf7f28238be6f85d: Scheduling MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6): perf score=1.000000
I20260812 06:17:29.516275 26429 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.001s	sys 0.000s
I20260812 06:17:29.516736 26429 tablet_server.cc:179] TabletServer@127.25.207.65:0 shutting down...
I20260812 06:17:29.623742 26986 maintenance_manager.cc:643] P d84f018b4ad346d8bf7f28238be6f85d: MajorDeltaCompactionOp(256e3c350cd54726bac9fec967adbda6) complete. Timing: real 0.146s	user 0.099s	sys 0.047s Metrics: {"cfile_cache_hit":602,"cfile_cache_hit_bytes":24614715,"cfile_cache_miss":131,"cfile_cache_miss_bytes":8405916,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":359,"lbm_read_time_us":3303,"lbm_reads_lt_1ms":163,"lbm_write_time_us":29044,"lbm_writes_lt_1ms":743,"mutex_wait_us":75,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:17:29.624816 26429 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:29.625078 26429 tablet_replica.cc:333] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d: stopping tablet replica
I20260812 06:17:29.625279 26429 raft_consensus.cc:2243] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.625447 26429 raft_consensus.cc:2272] T 256e3c350cd54726bac9fec967adbda6 P d84f018b4ad346d8bf7f28238be6f85d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.629343 26429 tablet_server.cc:196] TabletServer@127.25.207.65:0 shutdown complete.
I20260812 06:17:29.682060 26429 master.cc:562] Master@127.25.207.126:40085 shutting down...
I20260812 06:17:29.685271 26429 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.685463 26429 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.685550 26429 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1d0b3a8112fe4f9c8b34b8d319e00e7f: stopping tablet replica
I20260812 06:17:29.697782 26429 master.cc:584] Master@127.25.207.126:40085 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5823 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10616 ms total)

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