[==========] 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:57.770040  3730 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.164.190:32915
I20260812 06:17:57.770999  3730 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:57.771560  3730 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.778195  3736 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:57.778172  3738 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:57.778462  3730 server_base.cc:1061] running on GCE node
W20260812 06:17:57.778462  3735 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:57.779003  3730 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.779130  3730 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:57.779172  3730 hybrid_clock.cc:648] HybridClock initialized: now 1786515477779170 us; error 0 us; skew 500 ppm
I20260812 06:17:57.781023  3730 webserver.cc:533] Webserver started at http://127.3.164.190:42869/ using document root <none> and password file <none>
I20260812 06:17:57.781541  3730 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.781598  3730 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.781791  3730 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.783407  3730 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/master-0-root/instance:
uuid: "3b7ee903285b4a0fb3d86fbf90609b56"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0b58"
I20260812 06:17:57.787006  3730 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.005s
I20260812 06:17:57.789146  3743 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:57.790246  3730 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:17:57.790400  3730 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/master-0-root
uuid: "3b7ee903285b4a0fb3d86fbf90609b56"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0b58"
I20260812 06:17:57.790514  3730 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-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:57.811681  3730 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.812436  3730 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:57.812633  3730 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.821030  3730 rpc_server.cc:307] RPC server started. Bound to: 127.3.164.190:32915
I20260812 06:17:57.821103  3804 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.164.190:32915 every 8 connection(s)
I20260812 06:17:57.823535  3805 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:57.829596  3805 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56: Bootstrap starting.
I20260812 06:17:57.832187  3805 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.833293  3805 log.cc:826] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:57.835253  3805 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56: No bootstrap required, opened a new log
I20260812 06:17:57.838404  3805 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b7ee903285b4a0fb3d86fbf90609b56" member_type: VOTER }
I20260812 06:17:57.838598  3805 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.838676  3805 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3b7ee903285b4a0fb3d86fbf90609b56, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.839368  3805 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [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: "3b7ee903285b4a0fb3d86fbf90609b56" member_type: VOTER }
I20260812 06:17:57.839524  3805 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.839615  3805 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.839847  3805 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.840868  3805 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b7ee903285b4a0fb3d86fbf90609b56" member_type: VOTER }
I20260812 06:17:57.841382  3805 leader_election.cc:304] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [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: 3b7ee903285b4a0fb3d86fbf90609b56; no voters: 
I20260812 06:17:57.841768  3805 leader_election.cc:290] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.842120  3808 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.842404  3808 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 1 LEADER]: Becoming Leader. State: Replica: 3b7ee903285b4a0fb3d86fbf90609b56, State: Running, Role: LEADER
I20260812 06:17:57.842921  3808 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [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: "3b7ee903285b4a0fb3d86fbf90609b56" member_type: VOTER }
I20260812 06:17:57.842917  3805 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:57.844895  3809 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3b7ee903285b4a0fb3d86fbf90609b56" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b7ee903285b4a0fb3d86fbf90609b56" member_type: VOTER } }
I20260812 06:17:57.844928  3810 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3b7ee903285b4a0fb3d86fbf90609b56. Latest consensus state: current_term: 1 leader_uuid: "3b7ee903285b4a0fb3d86fbf90609b56" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b7ee903285b4a0fb3d86fbf90609b56" member_type: VOTER } }
I20260812 06:17:57.845037  3809 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.845037  3810 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.845530  3820 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:57.845690  3730 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:57.848361  3820 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:57.853494  3820 catalog_manager.cc:1383] Generated new cluster ID: 98cffa0a0f1248a5990096ba9eef5f04
I20260812 06:17:57.853587  3820 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:57.881387  3820 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:57.882691  3820 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:57.897622  3820 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56: Generated new TSK 0
I20260812 06:17:57.898471  3820 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:57.911114  3730 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.914585  3827 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:57.914585  3828 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:57.914845  3730 server_base.cc:1061] running on GCE node
W20260812 06:17:57.914706  3831 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:57.915136  3730 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.915205  3730 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:57.915232  3730 hybrid_clock.cc:648] HybridClock initialized: now 1786515477915231 us; error 0 us; skew 500 ppm
I20260812 06:17:57.916328  3730 webserver.cc:533] Webserver started at http://127.3.164.129:35537/ using document root <none> and password file <none>
I20260812 06:17:57.916548  3730 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.916628  3730 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.916713  3730 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.917165  3730 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/instance:
uuid: "96224b5d175740e791cc2a19e51e5570"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0b58"
I20260812 06:17:57.918869  3730 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:57.920010  3837 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:57.920305  3730 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:57.920411  3730 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root
uuid: "96224b5d175740e791cc2a19e51e5570"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0b58"
I20260812 06:17:57.920504  3730 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-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:57.937198  3730 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.937752  3730 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.938294  3730 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:57.939252  3730 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:57.939311  3730 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.939353  3730 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:57.939421  3730 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.947104  3730 rpc_server.cc:307] RPC server started. Bound to: 127.3.164.129:35825
I20260812 06:17:57.947140  3909 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.164.129:35825 every 8 connection(s)
I20260812 06:17:57.963059  3910 heartbeater.cc:344] Connected to a master server at 127.3.164.190:32915
I20260812 06:17:57.963356  3910 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:57.963948  3910 heartbeater.cc:507] Master 127.3.164.190:32915 requested a full tablet report, sending...
I20260812 06:17:57.965528  3764 ts_manager.cc:194] Registered new tserver with Master: 96224b5d175740e791cc2a19e51e5570 (127.3.164.129:35825)
I20260812 06:17:57.967159  3764 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54838
I20260812 06:17:57.967474  3730 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.019635785s
I20260812 06:17:57.978826  3764 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54852:
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:57.993212  3868 tablet_service.cc:1511] Processing CreateTablet for tablet f1121912a3a74865bf8976d36c44d93a (DEFAULT_TABLE table=heavy-update-compaction-test [id=4b561a602b104b7ab20d964047eafe9a]), partition=
I20260812 06:17:57.993747  3868 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f1121912a3a74865bf8976d36c44d93a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:57.996129  3923 tablet_bootstrap.cc:492] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Bootstrap starting.
I20260812 06:17:57.997380  3923 tablet_bootstrap.cc:654] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.998837  3923 tablet_bootstrap.cc:492] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: No bootstrap required, opened a new log
I20260812 06:17:57.998966  3923 ts_tablet_manager.cc:1403] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:57.999423  3923 raft_consensus.cc:359] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96224b5d175740e791cc2a19e51e5570" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 35825 } }
I20260812 06:17:57.999547  3923 raft_consensus.cc:385] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.999593  3923 raft_consensus.cc:740] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 96224b5d175740e791cc2a19e51e5570, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.999739  3923 consensus_queue.cc:260] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [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: "96224b5d175740e791cc2a19e51e5570" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 35825 } }
I20260812 06:17:57.999854  3923 raft_consensus.cc:399] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.999903  3923 raft_consensus.cc:493] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.999959  3923 raft_consensus.cc:3060] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:58.000941  3923 raft_consensus.cc:515] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96224b5d175740e791cc2a19e51e5570" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 35825 } }
I20260812 06:17:58.001092  3923 leader_election.cc:304] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [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: 96224b5d175740e791cc2a19e51e5570; no voters: 
I20260812 06:17:58.001412  3923 leader_election.cc:290] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:58.001510  3926 raft_consensus.cc:2804] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:58.001688  3926 raft_consensus.cc:697] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 1 LEADER]: Becoming Leader. State: Replica: 96224b5d175740e791cc2a19e51e5570, State: Running, Role: LEADER
I20260812 06:17:58.001793  3923 ts_tablet_manager.cc:1434] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:58.001899  3926 consensus_queue.cc:237] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [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: "96224b5d175740e791cc2a19e51e5570" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 35825 } }
I20260812 06:17:58.002115  3910 heartbeater.cc:499] Master 127.3.164.190:32915 was elected leader, sending a full tablet report...
I20260812 06:17:58.004859  3764 catalog_manager.cc:5719] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 reported cstate change: term changed from 0 to 1, leader changed from <none> to 96224b5d175740e791cc2a19e51e5570 (127.3.164.129). New cstate: current_term: 1 leader_uuid: "96224b5d175740e791cc2a19e51e5570" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96224b5d175740e791cc2a19e51e5570" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 35825 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:58.073612  3730 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.018s	sys 0.008s
I20260812 06:17:58.198369  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushMRSOp(f1121912a3a74865bf8976d36c44d93a): perf score=15.086190
I20260812 06:17:58.381152  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushMRSOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.182s	user 0.134s	sys 0.044s Metrics: {"bytes_written":13374125,"cfile_init":1,"compiler_manager_pool.queue_time_us":225,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1003,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45640,"lbm_writes_lt_1ms":683,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":177792,"thread_start_us":140,"threads_started":1,"update_count":1630}
I20260812 06:17:58.382488  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a): 12308960 bytes on disk
I20260812 06:17:58.383270  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.383764  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=3.181125
I20260812 06:17:58.403566  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4800074,"delete_count":0,"lbm_write_time_us":7717,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:17:58.404065  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling LogGCOp(f1121912a3a74865bf8976d36c44d93a): free 8725963 bytes of WAL
I20260812 06:17:58.404425  3844 log_reader.cc:385] T f1121912a3a74865bf8976d36c44d93a: removed 1 log segments from log reader
I20260812 06:17:58.404505  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000001 (ops 1-6)
I20260812 06:17:58.406482  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: LogGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:58.406813  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.196750
I20260812 06:17:58.413932  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.007s	user 0.002s	sys 0.003s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":2374,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:17:58.414590  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:58.605379  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.191s	user 0.120s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733813,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":879,"lbm_read_time_us":12223,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33003,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24576,"thread_start_us":319,"threads_started":5,"update_count":2500}
I20260812 06:17:58.605944  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:17:58.657578  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.051s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16878,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.658088  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:58.668615  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.669253  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:58.801795  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.132s	user 0.084s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":232,"lbm_read_time_us":8413,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26832,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:58.802325  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:17:58.851130  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.049s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:17:58.851637  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:58.862640  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.863351  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:58.991254  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.128s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":291,"lbm_read_time_us":10220,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23646,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:58.991845  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:17:59.043735  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.052s	user 0.021s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.044612  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:59.062100  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.062613  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:59.218681  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.156s	user 0.117s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":899,"lbm_read_time_us":13711,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":27500,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:59.219290  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:17:59.250065  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.031s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.250607  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:59.355595  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.105s	user 0.084s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1262,"lbm_read_time_us":7061,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18946,"lbm_writes_lt_1ms":343,"mutex_wait_us":340,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":1500}
I20260812 06:17:59.356362  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:17:59.404342  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19956,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.404861  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:59.415635  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.416416  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:59.540621  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.124s	user 0.111s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":114,"lbm_read_time_us":8252,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25167,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:59.541260  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:17:59.598682  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.057s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16819,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.599218  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:59.609993  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.610446  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushMRSOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:59.649638  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushMRSOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.039s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1665,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1617,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:59.650475  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling LogGCOp(f1121912a3a74865bf8976d36c44d93a): free 115943138 bytes of WAL
I20260812 06:17:59.650718  3844 log_reader.cc:385] T f1121912a3a74865bf8976d36c44d93a: removed 11 log segments from log reader
I20260812 06:17:59.650763  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000002 (ops 7-11)
I20260812 06:17:59.650794  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000003 (ops 12-16)
I20260812 06:17:59.650858  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000004 (ops 17-21)
I20260812 06:17:59.650908  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000005 (ops 22-26)
I20260812 06:17:59.650960  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000006 (ops 27-31)
I20260812 06:17:59.651016  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000007 (ops 32-36)
I20260812 06:17:59.651058  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000008 (ops 37-41)
I20260812 06:17:59.651094  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000009 (ops 42-46)
I20260812 06:17:59.651134  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000010 (ops 47-51)
I20260812 06:17:59.651170  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000011 (ops 52-56)
I20260812 06:17:59.651206  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000012 (ops 57-61)
I20260812 06:17:59.677572  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: LogGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:59.678051  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a): 447 bytes on disk
I20260812 06:17:59.678508  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.679073  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=3.181125
I20260812 06:17:59.693907  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4349,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:59.694373  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling LogGCOp(f1121912a3a74865bf8976d36c44d93a): free 12017983 bytes of WAL
I20260812 06:17:59.694671  3844 log_reader.cc:385] T f1121912a3a74865bf8976d36c44d93a: removed 1 log segments from log reader
I20260812 06:17:59.694742  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000013 (ops 62-66)
I20260812 06:17:59.698040  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: LogGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:59.698428  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:59.713238  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5284,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.713826  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:17:59.908507  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.194s	user 0.124s	sys 0.070s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":317,"lbm_read_time_us":13028,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31584,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":54272,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:59.909353  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:17:59.969909  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.060s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20949,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.970432  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:17:59.982645  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.983202  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:00.157555  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.174s	user 0.126s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":607,"lbm_read_time_us":12482,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28532,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:18:00.158161  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:00.213546  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.055s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24051,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.214082  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:00.229725  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.230281  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:00.407070  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.177s	user 0.098s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":13955,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28994,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:18:00.407768  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:00.468093  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.060s	user 0.018s	sys 0.034s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.468665  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:00.479482  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.480032  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:00.666277  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.186s	user 0.128s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1091,"lbm_read_time_us":13106,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31687,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:00.666981  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:00.715736  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.049s	user 0.023s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18372,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.716380  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:00.737429  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.021s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.737969  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:00.929824  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.192s	user 0.114s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":12823,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32005,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:18:00.930581  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:00.981243  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.050s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19519,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.981786  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:00.993170  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.993933  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:01.171249  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.177s	user 0.114s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":487,"lbm_read_time_us":9677,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29003,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:01.172340  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=11.118625
I20260812 06:18:01.207495  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15496,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.208309  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:01.225854  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5755,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.226450  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushMRSOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:01.280889  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushMRSOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.054s	user 0.026s	sys 0.008s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1509,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2200,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:01.281679  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling LogGCOp(f1121912a3a74865bf8976d36c44d93a): free 121006432 bytes of WAL
I20260812 06:18:01.281929  3844 log_reader.cc:385] T f1121912a3a74865bf8976d36c44d93a: removed 12 log segments from log reader
I20260812 06:18:01.281993  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000014 (ops 67-71)
I20260812 06:18:01.282054  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000015 (ops 72-76)
I20260812 06:18:01.282114  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000016 (ops 77-81)
I20260812 06:18:01.282162  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000017 (ops 82-86)
I20260812 06:18:01.282219  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000018 (ops 87-91)
I20260812 06:18:01.282259  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000019 (ops 92-96)
I20260812 06:18:01.282295  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000020 (ops 97-100)
I20260812 06:18:01.282332  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000021 (ops 101-105)
I20260812 06:18:01.282369  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000022 (ops 106-110)
I20260812 06:18:01.282411  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000023 (ops 111-115)
I20260812 06:18:01.282449  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000024 (ops 116-120)
I20260812 06:18:01.282485  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000025 (ops 121-125)
I20260812 06:18:01.311122  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: LogGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:01.311633  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a): 493 bytes on disk
I20260812 06:18:01.312239  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a) 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:18:01.312953  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=7.149875
I20260812 06:18:01.338958  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.026s	user 0.016s	sys 0.007s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11358,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:01.339525  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:01.355324  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6193,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.355901  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:01.599092  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.243s	user 0.164s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938769,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":388,"lbm_read_time_us":15663,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42378,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":47616,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:01.599807  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=18.063937
I20260812 06:18:01.672720  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.073s	user 0.027s	sys 0.036s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29490,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:01.673183  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:01.685158  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.685735  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:01.875478  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.190s	user 0.121s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":395,"lbm_read_time_us":13822,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33220,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:18:01.876194  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:01.919513  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.043s	user 0.031s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19405,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.920145  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:01.942174  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.022s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.942771  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:02.118616  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.175s	user 0.127s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":488,"lbm_read_time_us":13372,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29190,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:02.119280  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:02.179939  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.060s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24902,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.180609  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:02.193603  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.194742  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:02.386554  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.192s	user 0.124s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1351,"lbm_read_time_us":13339,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30003,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:18:02.387455  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=14.095187
I20260812 06:18:02.451941  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.064s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22764,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.452625  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:02.470605  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.471294  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:02.650238  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.179s	user 0.115s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1109,"lbm_read_time_us":13075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31269,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:02.650928  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=11.118625
I20260812 06:18:02.680712  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12783,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.681556  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:02.695308  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.695911  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:02.852910  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.157s	user 0.113s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":8234,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24335,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:02.853467  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=11.118625
I20260812 06:18:02.893256  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.040s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17177,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.893910  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:02.911773  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.912352  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:02.925968  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5023,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.926532  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushMRSOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:02.964150  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushMRSOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.037s	user 0.032s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1449,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2404,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:02.965098  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling LogGCOp(f1121912a3a74865bf8976d36c44d93a): free 133024580 bytes of WAL
I20260812 06:18:02.965353  3844 log_reader.cc:385] T f1121912a3a74865bf8976d36c44d93a: removed 13 log segments from log reader
I20260812 06:18:02.965404  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000026 (ops 126-130)
I20260812 06:18:02.965435  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000027 (ops 131-135)
I20260812 06:18:02.965454  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000028 (ops 136-140)
I20260812 06:18:02.965476  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000029 (ops 141-145)
I20260812 06:18:02.965492  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000030 (ops 146-150)
I20260812 06:18:02.965509  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000031 (ops 151-155)
I20260812 06:18:02.965528  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000032 (ops 156-160)
I20260812 06:18:02.965547  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000033 (ops 161-164)
I20260812 06:18:02.965569  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000034 (ops 165-169)
I20260812 06:18:02.965588  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000035 (ops 170-174)
I20260812 06:18:02.965608  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000036 (ops 175-179)
I20260812 06:18:02.965624  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000037 (ops 180-184)
I20260812 06:18:02.965644  3844 log.cc:1079] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/f1121912a3a74865bf8976d36c44d93a/wal-000000038 (ops 185-189)
I20260812 06:18:02.998562  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: LogGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:02.999078  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a): 492 bytes on disk
I20260812 06:18:02.999773  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: UndoDeltaBlockGCOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.000434  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=3.181125
I20260812 06:18:03.014654  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4923146,"delete_count":0,"lbm_write_time_us":5701,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 06:18:03.015216  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=2.188937
I20260812 06:18:03.037766  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.022s	user 0.003s	sys 0.018s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:03.038460  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a): perf score=1.000000
I20260812 06:18:03.185863  3730 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.112s	user 1.870s	sys 0.177s
I20260812 06:18:03.248651  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: MajorDeltaCompactionOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.210s	user 0.138s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938879,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16050,"lbm_reads_lt_1ms":771,"lbm_write_time_us":35805,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:18:03.249135  3911 maintenance_manager.cc:419] P 96224b5d175740e791cc2a19e51e5570: Scheduling FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a): perf score=10.126437
I20260812 06:18:03.276051  3730 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.002s	sys 0.000s
I20260812 06:18:03.276963  3730 tablet_server.cc:179] TabletServer@127.3.164.129:0 shutting down...
I20260812 06:18:03.284610  3844 maintenance_manager.cc:643] P 96224b5d175740e791cc2a19e51e5570: FlushDeltaMemStoresOp(f1121912a3a74865bf8976d36c44d93a) complete. Timing: real 0.035s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14477,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.285185  3730 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:03.285615  3730 tablet_replica.cc:333] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570: stopping tablet replica
I20260812 06:18:03.285805  3730 raft_consensus.cc:2243] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.285995  3730 raft_consensus.cc:2272] T f1121912a3a74865bf8976d36c44d93a P 96224b5d175740e791cc2a19e51e5570 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.292363  3730 tablet_server.cc:196] TabletServer@127.3.164.129:0 shutdown complete.
I20260812 06:18:03.316838  3730 master.cc:562] Master@127.3.164.190:32915 shutting down...
I20260812 06:18:03.320607  3730 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.320817  3730 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.320917  3730 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3b7ee903285b4a0fb3d86fbf90609b56: stopping tablet replica
I20260812 06:18:03.333602  3730 master.cc:584] Master@127.3.164.190:32915 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5657 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:03.439136  3730 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.164.190:33089
I20260812 06:18:03.439579  3730 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.441974  3947 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.442061  3730 server_base.cc:1061] running on GCE node
W20260812 06:18:03.442058  3949 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.441974  3946 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.442453  3730 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.442497  3730 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.442512  3730 hybrid_clock.cc:648] HybridClock initialized: now 1786515483442513 us; error 0 us; skew 500 ppm
I20260812 06:18:03.443435  3730 webserver.cc:533] Webserver started at http://127.3.164.190:38869/ using document root <none> and password file <none>
I20260812 06:18:03.443575  3730 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.443619  3730 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.443674  3730 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.444028  3730 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/master-0-root/instance:
uuid: "9b37710c517d454bbad37e9a6edff1f4"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0b58"
I20260812 06:18:03.445701  3730 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:03.446729  3956 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.447043  3730 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.447113  3730 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/master-0-root
uuid: "9b37710c517d454bbad37e9a6edff1f4"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0b58"
I20260812 06:18:03.447183  3730 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.474020  3730 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.474429  3730 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.478642  3730 rpc_server.cc:307] RPC server started. Bound to: 127.3.164.190:33089
I20260812 06:18:03.480711  4011 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.480733  4010 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.164.190:33089 every 8 connection(s)
I20260812 06:18:03.485992  4011 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4: Bootstrap starting.
I20260812 06:18:03.486743  4011 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.487746  4011 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4: No bootstrap required, opened a new log
I20260812 06:18:03.488104  4011 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b37710c517d454bbad37e9a6edff1f4" member_type: VOTER }
I20260812 06:18:03.488188  4011 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.488210  4011 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9b37710c517d454bbad37e9a6edff1f4, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.488476  4011 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [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: "9b37710c517d454bbad37e9a6edff1f4" member_type: VOTER }
I20260812 06:18:03.488550  4011 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.488597  4011 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.488660  4011 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.489347  4011 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b37710c517d454bbad37e9a6edff1f4" member_type: VOTER }
I20260812 06:18:03.489494  4011 leader_election.cc:304] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [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: 9b37710c517d454bbad37e9a6edff1f4; no voters: 
I20260812 06:18:03.489722  4011 leader_election.cc:290] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.489868  4014 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.490079  4014 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 1 LEADER]: Becoming Leader. State: Replica: 9b37710c517d454bbad37e9a6edff1f4, State: Running, Role: LEADER
I20260812 06:18:03.490160  4011 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:03.490250  4014 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [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: "9b37710c517d454bbad37e9a6edff1f4" member_type: VOTER }
I20260812 06:18:03.490716  4016 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9b37710c517d454bbad37e9a6edff1f4. Latest consensus state: current_term: 1 leader_uuid: "9b37710c517d454bbad37e9a6edff1f4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b37710c517d454bbad37e9a6edff1f4" member_type: VOTER } }
I20260812 06:18:03.490713  4015 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9b37710c517d454bbad37e9a6edff1f4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9b37710c517d454bbad37e9a6edff1f4" member_type: VOTER } }
I20260812 06:18:03.490844  4015 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.491053  4016 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.491118  4020 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:03.492450  4020 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:03.492704  3730 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:03.494432  4020 catalog_manager.cc:1383] Generated new cluster ID: 0ac20676b9d44c2b940f77c3c5a9b142
I20260812 06:18:03.494494  4020 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:03.514880  4020 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:03.515527  4020 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:03.522253  4020 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4: Generated new TSK 0
I20260812 06:18:03.522446  4020 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:03.525144  3730 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.527280  4033 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.527372  4036 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.527441  3730 server_base.cc:1061] running on GCE node
W20260812 06:18:03.527329  4034 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.527740  3730 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.527784  3730 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.527801  3730 hybrid_clock.cc:648] HybridClock initialized: now 1786515483527800 us; error 0 us; skew 500 ppm
I20260812 06:18:03.528671  3730 webserver.cc:533] Webserver started at http://127.3.164.129:38217/ using document root <none> and password file <none>
I20260812 06:18:03.528812  3730 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.528858  3730 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.528908  3730 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.529263  3730 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/instance:
uuid: "6fd68912b0f8478d8ec9e2666bf13780"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0b58"
I20260812 06:18:03.530732  3730 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:03.531699  4041 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.532079  3730 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:03.532146  3730 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root
uuid: "6fd68912b0f8478d8ec9e2666bf13780"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0b58"
I20260812 06:18:03.532243  3730 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.543788  3730 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.544214  3730 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.544598  3730 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:03.545101  3730 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:03.545142  3730 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.545208  3730 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:03.545248  3730 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.549849  3730 rpc_server.cc:307] RPC server started. Bound to: 127.3.164.129:39237
I20260812 06:18:03.550958  4114 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.164.129:39237 every 8 connection(s)
I20260812 06:18:03.560122  4115 heartbeater.cc:344] Connected to a master server at 127.3.164.190:33089
I20260812 06:18:03.560351  4115 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:03.560631  4115 heartbeater.cc:507] Master 127.3.164.190:33089 requested a full tablet report, sending...
I20260812 06:18:03.561308  3973 ts_manager.cc:194] Registered new tserver with Master: 6fd68912b0f8478d8ec9e2666bf13780 (127.3.164.129:39237)
I20260812 06:18:03.562021  3973 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38936
I20260812 06:18:03.562086  3730 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011289441s
I20260812 06:18:03.569499  3973 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38940:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:03.578187  4075 tablet_service.cc:1511] Processing CreateTablet for tablet 2cb9f38300c140498002bc1a0322b101 (DEFAULT_TABLE table=heavy-update-compaction-test [id=64bf409cde994c9b9a8effe8ff7731d4]), partition=
I20260812 06:18:03.578496  4075 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2cb9f38300c140498002bc1a0322b101. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.580689  4128 tablet_bootstrap.cc:492] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Bootstrap starting.
I20260812 06:18:03.581593  4128 tablet_bootstrap.cc:654] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.582679  4128 tablet_bootstrap.cc:492] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: No bootstrap required, opened a new log
I20260812 06:18:03.582760  4128 ts_tablet_manager.cc:1403] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:03.583189  4128 raft_consensus.cc:359] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fd68912b0f8478d8ec9e2666bf13780" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 39237 } }
I20260812 06:18:03.583281  4128 raft_consensus.cc:385] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.583305  4128 raft_consensus.cc:740] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6fd68912b0f8478d8ec9e2666bf13780, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.583523  4128 consensus_queue.cc:260] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [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: "6fd68912b0f8478d8ec9e2666bf13780" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 39237 } }
I20260812 06:18:03.583663  4128 raft_consensus.cc:399] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.583714  4128 raft_consensus.cc:493] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.583758  4128 raft_consensus.cc:3060] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.584714  4128 raft_consensus.cc:515] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fd68912b0f8478d8ec9e2666bf13780" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 39237 } }
I20260812 06:18:03.584877  4128 leader_election.cc:304] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [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: 6fd68912b0f8478d8ec9e2666bf13780; no voters: 
I20260812 06:18:03.585127  4128 leader_election.cc:290] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.585261  4131 raft_consensus.cc:2804] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.585494  4131 raft_consensus.cc:697] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 1 LEADER]: Becoming Leader. State: Replica: 6fd68912b0f8478d8ec9e2666bf13780, State: Running, Role: LEADER
I20260812 06:18:03.585500  4128 ts_tablet_manager.cc:1434] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:03.585556  4115 heartbeater.cc:499] Master 127.3.164.190:33089 was elected leader, sending a full tablet report...
I20260812 06:18:03.585664  4131 consensus_queue.cc:237] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [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: "6fd68912b0f8478d8ec9e2666bf13780" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 39237 } }
I20260812 06:18:03.587073  3973 catalog_manager.cc:5719] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6fd68912b0f8478d8ec9e2666bf13780 (127.3.164.129). New cstate: current_term: 1 leader_uuid: "6fd68912b0f8478d8ec9e2666bf13780" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fd68912b0f8478d8ec9e2666bf13780" member_type: VOTER last_known_addr { host: "127.3.164.129" port: 39237 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:03.648486  3730 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.019s	sys 0.004s
I20260812 06:18:03.801435  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushMRSOp(2cb9f38300c140498002bc1a0322b101): perf score=19.054940
I20260812 06:18:03.966820  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushMRSOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.165s	user 0.109s	sys 0.052s Metrics: {"bytes_written":13661282,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":940,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42498,"lbm_writes_lt_1ms":790,"mutex_wait_us":186,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":27904,"update_count":1665}
I20260812 06:18:03.967459  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling LogGCOp(2cb9f38300c140498002bc1a0322b101): free 20743880 bytes of WAL
I20260812 06:18:03.967715  4046 log_reader.cc:385] T 2cb9f38300c140498002bc1a0322b101: removed 2 log segments from log reader
I20260812 06:18:03.967758  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000001 (ops 1-6)
I20260812 06:18:03.967790  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000002 (ops 7-11)
I20260812 06:18:03.973141  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: LogGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:03.973657  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101): 16411396 bytes on disk
I20260812 06:18:03.974287  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.974759  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=1.196750
I20260812 06:18:03.992790  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.018s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3159084,"delete_count":0,"lbm_write_time_us":5134,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:18:03.993253  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:04.006839  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5219,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.007409  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:04.199290  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.192s	user 0.117s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774771,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":290,"lbm_read_time_us":13562,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30273,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"thread_start_us":328,"threads_started":5,"update_count":2500}
I20260812 06:18:04.199955  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:04.262944  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.063s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22159,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.263494  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:04.274312  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.275156  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:04.448747  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.173s	user 0.108s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":12580,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27263,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:04.449373  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:04.524991  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.075s	user 0.039s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30397,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.525554  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:04.537935  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.538470  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:04.717989  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.179s	user 0.137s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":12797,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32866,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:04.718643  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:04.783790  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.065s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22889,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.784385  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:04.795527  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.796182  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:04.979461  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.182s	user 0.096s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":13402,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30742,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:04.979990  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:05.043903  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.064s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20974,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.044548  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:05.055519  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.055974  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:05.232012  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.176s	user 0.112s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":11744,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31076,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:18:05.232797  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=11.118625
I20260812 06:18:05.264348  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.031s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13788,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:05.264891  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:05.280723  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5787,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.281203  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushMRSOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:05.314150  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushMRSOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.033s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":305,"dirs.run_wall_time_us":1690,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2131,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1920}
I20260812 06:18:05.315156  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling LogGCOp(2cb9f38300c140498002bc1a0322b101): free 112692377 bytes of WAL
I20260812 06:18:05.315534  4046 log_reader.cc:385] T 2cb9f38300c140498002bc1a0322b101: removed 11 log segments from log reader
I20260812 06:18:05.315639  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000003 (ops 12-16)
I20260812 06:18:05.315759  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000004 (ops 17-21)
I20260812 06:18:05.315809  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000005 (ops 22-26)
I20260812 06:18:05.315891  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000006 (ops 27-31)
I20260812 06:18:05.315963  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000007 (ops 32-36)
I20260812 06:18:05.316025  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000008 (ops 37-41)
I20260812 06:18:05.316061  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000009 (ops 42-46)
I20260812 06:18:05.316124  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000010 (ops 47-51)
I20260812 06:18:05.316195  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000011 (ops 52-56)
I20260812 06:18:05.316244  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000012 (ops 57-61)
I20260812 06:18:05.316336  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000013 (ops 62-66)
I20260812 06:18:05.344941  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: LogGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.030s	user 0.002s	sys 0.026s Metrics: {}
I20260812 06:18:05.345366  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101): 461 bytes on disk
I20260812 06:18:05.345793  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101) 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:18:05.346313  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=3.181125
I20260812 06:18:05.367260  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.021s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4598,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:05.367754  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling LogGCOp(2cb9f38300c140498002bc1a0322b101): free 11564875 bytes of WAL
I20260812 06:18:05.367965  4046 log_reader.cc:385] T 2cb9f38300c140498002bc1a0322b101: removed 1 log segments from log reader
I20260812 06:18:05.368031  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000014 (ops 67-70)
I20260812 06:18:05.370508  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: LogGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:05.370811  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:05.381206  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.381856  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:05.586844  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.205s	user 0.136s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":625,"lbm_read_time_us":15251,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34116,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:05.587622  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:05.643306  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.055s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":2000}
I20260812 06:18:05.643819  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:05.654911  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4324,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.655383  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:05.845360  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.190s	user 0.120s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":14341,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30047,"lbm_writes_lt_1ms":543,"mutex_wait_us":80,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:05.846021  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:05.910347  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.064s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20214,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.910899  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:05.921720  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.922231  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:06.108036  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.186s	user 0.127s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":737,"lbm_read_time_us":13931,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29555,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:18:06.108750  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=11.118625
I20260812 06:18:06.158283  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.049s	user 0.017s	sys 0.030s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21365,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.158824  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:06.188400  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.029s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.189003  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:06.203367  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5493,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.204032  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:06.391054  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.187s	user 0.133s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":893,"lbm_read_time_us":13607,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29611,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:18:06.391793  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:06.443882  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.052s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21044,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.444479  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:06.465692  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.466428  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:06.646108  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.179s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":13968,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29039,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:06.646771  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=11.118625
I20260812 06:18:06.676730  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.030s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12917,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.677927  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:06.692693  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4924,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.694090  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:06.822093  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.128s	user 0.099s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":7281,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27061,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":71296,"update_count":2000}
I20260812 06:18:06.822947  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=10.126437
I20260812 06:18:06.857390  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.034s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15152,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.858033  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:06.875039  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.875582  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushMRSOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:06.903582  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushMRSOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.028s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1533,"drs_written":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1491,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:06.904218  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling LogGCOp(2cb9f38300c140498002bc1a0322b101): free 120553382 bytes of WAL
I20260812 06:18:06.904565  4046 log_reader.cc:385] T 2cb9f38300c140498002bc1a0322b101: removed 12 log segments from log reader
I20260812 06:18:06.904621  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000015 (ops 71-75)
I20260812 06:18:06.904651  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000016 (ops 76-80)
I20260812 06:18:06.904695  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000017 (ops 81-85)
I20260812 06:18:06.904738  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000018 (ops 86-90)
I20260812 06:18:06.904788  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000019 (ops 91-95)
I20260812 06:18:06.904826  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000020 (ops 96-100)
I20260812 06:18:06.904853  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000021 (ops 101-105)
I20260812 06:18:06.904912  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000022 (ops 106-110)
I20260812 06:18:06.904951  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000023 (ops 111-114)
I20260812 06:18:06.904991  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000024 (ops 115-119)
I20260812 06:18:06.905019  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000025 (ops 120-124)
I20260812 06:18:06.905058  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000026 (ops 125-128)
I20260812 06:18:06.933374  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: LogGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:06.933813  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101): 482 bytes on disk
I20260812 06:18:06.934330  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.934844  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=6.157687
I20260812 06:18:06.963191  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12093,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:06.963714  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:07.128633  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.165s	user 0.141s	sys 0.023s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":248,"lbm_read_time_us":12143,"lbm_reads_lt_1ms":665,"lbm_write_time_us":32184,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16000,"thread_start_us":117,"threads_started":1,"update_count":3000}
I20260812 06:18:07.129122  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:07.170106  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.041s	user 0.015s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18358,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.170651  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:07.185446  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.186008  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:07.343107  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.157s	user 0.100s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":11415,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31663,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:07.343781  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=11.118625
I20260812 06:18:07.382383  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16482,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:07.383112  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:07.399425  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5922,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.400050  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:07.530827  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.131s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":8424,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22547,"lbm_writes_lt_1ms":443,"mutex_wait_us":145,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:07.531589  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=11.118625
I20260812 06:18:07.581209  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.049s	user 0.035s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":23790,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:07.581768  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:07.604481  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.023s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.604969  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:07.615571  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.616091  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:07.795156  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.179s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1735,"lbm_read_time_us":13411,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29315,"lbm_writes_lt_1ms":543,"mutex_wait_us":728,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:07.795895  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:07.846675  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.051s	user 0.017s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18254,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.847266  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:07.858276  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.858800  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:08.041728  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.183s	user 0.124s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":786,"lbm_read_time_us":12665,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34649,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:18:08.042493  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=11.118625
I20260812 06:18:08.075842  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.033s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13689,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:08.076489  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:08.102404  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.026s	user 0.005s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.103040  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:08.293677  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.190s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":765,"lbm_read_time_us":10960,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30869,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:18:08.294459  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=14.095187
I20260812 06:18:08.352615  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.058s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23663,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.353138  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:08.365365  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.365911  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushMRSOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:08.403510  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushMRSOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.037s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1435,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1756,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:08.404289  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling LogGCOp(2cb9f38300c140498002bc1a0322b101): free 117302827 bytes of WAL
I20260812 06:18:08.404577  4046 log_reader.cc:385] T 2cb9f38300c140498002bc1a0322b101: removed 12 log segments from log reader
I20260812 06:18:08.404654  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000027 (ops 129-133)
I20260812 06:18:08.404712  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000028 (ops 134-138)
I20260812 06:18:08.404753  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000029 (ops 139-142)
I20260812 06:18:08.404795  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000030 (ops 143-147)
I20260812 06:18:08.404837  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000031 (ops 148-152)
I20260812 06:18:08.404879  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000032 (ops 153-157)
I20260812 06:18:08.404920  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000033 (ops 158-162)
I20260812 06:18:08.404961  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000034 (ops 163-167)
I20260812 06:18:08.405002  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000035 (ops 168-172)
I20260812 06:18:08.405043  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000036 (ops 173-176)
I20260812 06:18:08.405084  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000037 (ops 177-181)
I20260812 06:18:08.405125  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000038 (ops 182-186)
I20260812 06:18:08.436022  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: LogGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:08.436523  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101): 463 bytes on disk
I20260812 06:18:08.436990  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: UndoDeltaBlockGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.437552  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=3.181125
I20260812 06:18:08.463311  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.026s	user 0.006s	sys 0.017s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5000,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:08.463940  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling LogGCOp(2cb9f38300c140498002bc1a0322b101): free 11564891 bytes of WAL
I20260812 06:18:08.464224  4046 log_reader.cc:385] T 2cb9f38300c140498002bc1a0322b101: removed 1 log segments from log reader
I20260812 06:18:08.464313  4046 log.cc:1079] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: Deleting log segment in path: /tmp/dist-test-taskzZnqj7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477759027-3730-0/minicluster-data/ts-0-root/wals/2cb9f38300c140498002bc1a0322b101/wal-000000039 (ops 187-190)
I20260812 06:18:08.467379  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: LogGCOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:08.467839  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:08.483834  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5761,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.484467  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:08.748684  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.264s	user 0.152s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":596,"lbm_read_time_us":17838,"lbm_reads_lt_1ms":774,"lbm_write_time_us":52612,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":742,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":147,"threads_started":1,"update_count":3500}
I20260812 06:18:08.749390  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=15.087375
I20260812 06:18:08.761108  3730 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.112s	user 1.877s	sys 0.202s
I20260812 06:18:08.800748  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.051s	user 0.042s	sys 0.009s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24312,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:08.801412  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101): perf score=2.188937
I20260812 06:18:08.813472  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: FlushDeltaMemStoresOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.012s	user 0.008s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4585,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.814180  4116 maintenance_manager.cc:419] P 6fd68912b0f8478d8ec9e2666bf13780: Scheduling MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101): perf score=1.000000
I20260812 06:18:08.818118  3730 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.057s	user 0.001s	sys 0.000s
I20260812 06:18:08.818604  3730 tablet_server.cc:179] TabletServer@127.3.164.129:0 shutting down...
I20260812 06:18:08.955217  4046 maintenance_manager.cc:643] P 6fd68912b0f8478d8ec9e2666bf13780: MajorDeltaCompactionOp(2cb9f38300c140498002bc1a0322b101) complete. Timing: real 0.141s	user 0.105s	sys 0.036s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512285,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1130,"lbm_read_time_us":9212,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24088,"lbm_writes_lt_1ms":543,"mutex_wait_us":223,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:18:08.955894  3730 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:08.956207  3730 tablet_replica.cc:333] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780: stopping tablet replica
I20260812 06:18:08.956375  3730 raft_consensus.cc:2243] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.956559  3730 raft_consensus.cc:2272] T 2cb9f38300c140498002bc1a0322b101 P 6fd68912b0f8478d8ec9e2666bf13780 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.962226  3730 tablet_server.cc:196] TabletServer@127.3.164.129:0 shutdown complete.
I20260812 06:18:09.001681  3730 master.cc:562] Master@127.3.164.190:33089 shutting down...
I20260812 06:18:09.005573  3730 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:09.005779  3730 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:09.005883  3730 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9b37710c517d454bbad37e9a6edff1f4: stopping tablet replica
I20260812 06:18:09.018332  3730 master.cc:584] Master@127.3.164.190:33089 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5684 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11342 ms total)

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