[==========] 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:36.171895 15677 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.79.126:33409
I20260812 06:17:36.172910 15677 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:36.173499 15677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:36.180107 15688 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:36.180107 15685 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:36.180303 15677 server_base.cc:1061] running on GCE node
W20260812 06:17:36.180552 15684 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:36.181286 15677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:36.181398 15677 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:36.181471 15677 hybrid_clock.cc:648] HybridClock initialized: now 1786515456181468 us; error 0 us; skew 500 ppm
I20260812 06:17:36.183650 15677 webserver.cc:533] Webserver started at http://127.15.79.126:43325/ using document root <none> and password file <none>
I20260812 06:17:36.184273 15677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:36.184340 15677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:36.184612 15677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:36.186416 15677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/master-0-root/instance:
uuid: "766ab0f02a0945ac8113ba4b6204f9bd"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-sb2z"
I20260812 06:17:36.190465 15677 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.000s
I20260812 06:17:36.192966 15695 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:36.194144 15677 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:36.194299 15677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/master-0-root
uuid: "766ab0f02a0945ac8113ba4b6204f9bd"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-sb2z"
I20260812 06:17:36.194422 15677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-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:36.207082 15677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:36.207978 15677 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:36.208186 15677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:36.216791 15677 rpc_server.cc:307] RPC server started. Bound to: 127.15.79.126:33409
I20260812 06:17:36.216816 15786 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.79.126:33409 every 8 connection(s)
I20260812 06:17:36.219509 15789 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:36.225775 15789 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd: Bootstrap starting.
I20260812 06:17:36.228582 15789 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:36.229667 15789 log.cc:826] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:36.231736 15789 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd: No bootstrap required, opened a new log
I20260812 06:17:36.234948 15789 raft_consensus.cc:359] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766ab0f02a0945ac8113ba4b6204f9bd" member_type: VOTER }
I20260812 06:17:36.235145 15789 raft_consensus.cc:385] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:36.235250 15789 raft_consensus.cc:740] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 766ab0f02a0945ac8113ba4b6204f9bd, State: Initialized, Role: FOLLOWER
I20260812 06:17:36.236063 15789 consensus_queue.cc:260] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [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: "766ab0f02a0945ac8113ba4b6204f9bd" member_type: VOTER }
I20260812 06:17:36.236279 15789 raft_consensus.cc:399] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:36.236377 15789 raft_consensus.cc:493] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:36.236549 15789 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:36.237542 15789 raft_consensus.cc:515] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766ab0f02a0945ac8113ba4b6204f9bd" member_type: VOTER }
I20260812 06:17:36.238075 15789 leader_election.cc:304] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [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: 766ab0f02a0945ac8113ba4b6204f9bd; no voters: 
I20260812 06:17:36.238461 15789 leader_election.cc:290] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:36.238641 15795 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:36.238924 15795 raft_consensus.cc:697] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 1 LEADER]: Becoming Leader. State: Replica: 766ab0f02a0945ac8113ba4b6204f9bd, State: Running, Role: LEADER
I20260812 06:17:36.239382 15795 consensus_queue.cc:237] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [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: "766ab0f02a0945ac8113ba4b6204f9bd" member_type: VOTER }
I20260812 06:17:36.239672 15789 sys_catalog.cc:565] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:36.241469 15797 sys_catalog.cc:455] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "766ab0f02a0945ac8113ba4b6204f9bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766ab0f02a0945ac8113ba4b6204f9bd" member_type: VOTER } }
I20260812 06:17:36.241525 15798 sys_catalog.cc:455] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 766ab0f02a0945ac8113ba4b6204f9bd. Latest consensus state: current_term: 1 leader_uuid: "766ab0f02a0945ac8113ba4b6204f9bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766ab0f02a0945ac8113ba4b6204f9bd" member_type: VOTER } }
I20260812 06:17:36.241609 15797 sys_catalog.cc:458] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:36.241634 15798 sys_catalog.cc:458] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:36.242002 15812 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:36.245080 15812 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:36.245380 15677 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:36.251266 15812 catalog_manager.cc:1383] Generated new cluster ID: 43ae1a0d503f43bbbc4833e1a02a0428
I20260812 06:17:36.251354 15812 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:36.277707 15812 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:36.278939 15812 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:36.285813 15812 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd: Generated new TSK 0
I20260812 06:17:36.286659 15812 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:36.310451 15677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:36.313964 15833 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:36.313997 15829 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:36.314311 15677 server_base.cc:1061] running on GCE node
W20260812 06:17:36.314389 15830 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:36.314708 15677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:36.314800 15677 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:36.314831 15677 hybrid_clock.cc:648] HybridClock initialized: now 1786515456314829 us; error 0 us; skew 500 ppm
I20260812 06:17:36.315999 15677 webserver.cc:533] Webserver started at http://127.15.79.65:43645/ using document root <none> and password file <none>
I20260812 06:17:36.316205 15677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:36.316286 15677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:36.316375 15677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:36.316927 15677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/instance:
uuid: "4f655ca64650417b9a20ba7f43409c98"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-sb2z"
I20260812 06:17:36.318662 15677 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.003s	sys 0.000s
I20260812 06:17:36.319821 15838 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:36.320120 15677 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:36.320201 15677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root
uuid: "4f655ca64650417b9a20ba7f43409c98"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-sb2z"
I20260812 06:17:36.320298 15677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-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:36.330590 15677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:36.331125 15677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:36.331797 15677 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:36.332862 15677 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:36.332921 15677 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:36.333010 15677 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:36.333052 15677 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:36.340382 15677 rpc_server.cc:307] RPC server started. Bound to: 127.15.79.65:37945
I20260812 06:17:36.340618 15938 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.79.65:37945 every 8 connection(s)
I20260812 06:17:36.354727 15940 heartbeater.cc:344] Connected to a master server at 127.15.79.126:33409
I20260812 06:17:36.355026 15940 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:36.355626 15940 heartbeater.cc:507] Master 127.15.79.126:33409 requested a full tablet report, sending...
I20260812 06:17:36.357282 15727 ts_manager.cc:194] Registered new tserver with Master: 4f655ca64650417b9a20ba7f43409c98 (127.15.79.65:37945)
I20260812 06:17:36.357880 15677 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016498071s
I20260812 06:17:36.358614 15727 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58066
I20260812 06:17:36.368144 15727 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58082:
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:36.383208 15884 tablet_service.cc:1511] Processing CreateTablet for tablet 195637cc0b70438fb979da387ab39e5c (DEFAULT_TABLE table=heavy-update-compaction-test [id=85c8d583d1b446688a39011fc38659a1]), partition=
I20260812 06:17:36.383783 15884 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 195637cc0b70438fb979da387ab39e5c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:36.387210 15955 tablet_bootstrap.cc:492] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Bootstrap starting.
I20260812 06:17:36.388525 15955 tablet_bootstrap.cc:654] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:36.389732 15955 tablet_bootstrap.cc:492] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: No bootstrap required, opened a new log
I20260812 06:17:36.389827 15955 ts_tablet_manager.cc:1403] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:36.390344 15955 raft_consensus.cc:359] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f655ca64650417b9a20ba7f43409c98" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 37945 } }
I20260812 06:17:36.390479 15955 raft_consensus.cc:385] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:36.390519 15955 raft_consensus.cc:740] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f655ca64650417b9a20ba7f43409c98, State: Initialized, Role: FOLLOWER
I20260812 06:17:36.390717 15955 consensus_queue.cc:260] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [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: "4f655ca64650417b9a20ba7f43409c98" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 37945 } }
I20260812 06:17:36.390868 15955 raft_consensus.cc:399] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:36.390930 15955 raft_consensus.cc:493] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:36.390978 15955 raft_consensus.cc:3060] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:36.391993 15955 raft_consensus.cc:515] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f655ca64650417b9a20ba7f43409c98" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 37945 } }
I20260812 06:17:36.392172 15955 leader_election.cc:304] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [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: 4f655ca64650417b9a20ba7f43409c98; no voters: 
I20260812 06:17:36.392419 15955 leader_election.cc:290] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:36.392534 15958 raft_consensus.cc:2804] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:36.392831 15955 ts_tablet_manager.cc:1434] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:36.393021 15940 heartbeater.cc:499] Master 127.15.79.126:33409 was elected leader, sending a full tablet report...
I20260812 06:17:36.392834 15958 raft_consensus.cc:697] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 1 LEADER]: Becoming Leader. State: Replica: 4f655ca64650417b9a20ba7f43409c98, State: Running, Role: LEADER
I20260812 06:17:36.393466 15958 consensus_queue.cc:237] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [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: "4f655ca64650417b9a20ba7f43409c98" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 37945 } }
I20260812 06:17:36.396603 15727 catalog_manager.cc:5719] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4f655ca64650417b9a20ba7f43409c98 (127.15.79.65). New cstate: current_term: 1 leader_uuid: "4f655ca64650417b9a20ba7f43409c98" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f655ca64650417b9a20ba7f43409c98" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 37945 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:36.462788 15677 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.010s	sys 0.017s
I20260812 06:17:36.591935 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushMRSOp(195637cc0b70438fb979da387ab39e5c): perf score=15.086190
I20260812 06:17:36.755160 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushMRSOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.163s	user 0.112s	sys 0.032s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":3910,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1113,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37195,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":123,"threads_started":1,"update_count":1450}
I20260812 06:17:36.756506 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling LogGCOp(195637cc0b70438fb979da387ab39e5c): free 20743880 bytes of WAL
I20260812 06:17:36.756897 15845 log_reader.cc:385] T 195637cc0b70438fb979da387ab39e5c: removed 2 log segments from log reader
I20260812 06:17:36.756978 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000001 (ops 1-6)
I20260812 06:17:36.757043 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000002 (ops 7-11)
I20260812 06:17:36.763104 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: LogGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:36.763631 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:36.785717 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.022s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6856,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.786399 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:36.923944 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.137s	user 0.116s	sys 0.021s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1056,"lbm_read_time_us":9207,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26478,"lbm_writes_lt_1ms":433,"mutex_wait_us":53,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":332,"threads_started":5,"update_count":1950}
I20260812 06:17:36.924628 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=10.126437
I20260812 06:17:36.969063 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.044s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18226,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.969609 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c): 12719217 bytes on disk
I20260812 06:17:36.970180 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c) 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:17:36.970606 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:36.982429 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.982939 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:37.116390 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.133s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":8970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27723,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:17:37.117022 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=10.126437
I20260812 06:17:37.162983 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.046s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19612,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.163647 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:37.176604 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.177142 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:37.320943 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.144s	user 0.121s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":68,"lbm_read_time_us":10024,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28141,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.321854 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=11.118625
I20260812 06:17:37.366895 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.041s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14428,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.367599 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:37.383389 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.016s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.384083 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:37.548048 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.164s	user 0.096s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1365,"lbm_read_time_us":10392,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28518,"lbm_writes_lt_1ms":443,"mutex_wait_us":397,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:17:37.548628 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:37.600119 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.051s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20339,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.600607 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:37.616590 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.617149 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:37.791244 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.174s	user 0.123s	sys 0.048s 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":665,"lbm_read_time_us":13065,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32165,"lbm_writes_lt_1ms":543,"mutex_wait_us":337,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:17:37.792083 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=10.126437
I20260812 06:17:37.845417 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.053s	user 0.026s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":27397,"lbm_writes_1-10_ms":5,"lbm_writes_lt_1ms":298,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.846207 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:37.872902 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.026s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4348805,"delete_count":0,"lbm_write_time_us":7077,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:37.873449 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:37.884943 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:37.885826 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:38.037024 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.151s	user 0.121s	sys 0.027s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774804,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":330,"lbm_read_time_us":11938,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30859,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:17:38.037889 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=11.118625
I20260812 06:17:38.070719 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.033s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14376,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:38.071614 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:38.087481 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5210,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.088140 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushMRSOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:38.128662 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushMRSOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.040s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1558,"drs_written":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1967,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:38.129601 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=3.181125
I20260812 06:17:38.150115 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.020s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7107,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:38.150619 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling LogGCOp(195637cc0b70438fb979da387ab39e5c): free 120553387 bytes of WAL
I20260812 06:17:38.150872 15845 log_reader.cc:385] T 195637cc0b70438fb979da387ab39e5c: removed 12 log segments from log reader
I20260812 06:17:38.150916 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000003 (ops 12-16)
I20260812 06:17:38.150946 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000004 (ops 17-21)
I20260812 06:17:38.151015 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000005 (ops 22-26)
I20260812 06:17:38.151058 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000006 (ops 27-31)
I20260812 06:17:38.151101 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000007 (ops 32-36)
I20260812 06:17:38.151136 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000008 (ops 37-40)
I20260812 06:17:38.151176 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000009 (ops 41-45)
I20260812 06:17:38.151216 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000010 (ops 46-50)
I20260812 06:17:38.151257 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000011 (ops 51-55)
I20260812 06:17:38.151301 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000012 (ops 56-60)
I20260812 06:17:38.151335 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000013 (ops 61-64)
I20260812 06:17:38.151374 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000014 (ops 65-69)
I20260812 06:17:38.180219 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: LogGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:38.180986 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c): 473 bytes on disk
I20260812 06:17:38.181430 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.182030 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:38.206427 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.024s	user 0.001s	sys 0.017s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3941,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:38.207003 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:38.219043 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4680,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:38.219578 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:38.451411 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.232s	user 0.144s	sys 0.085s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979855,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":3014,"lbm_read_time_us":17048,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38615,"lbm_writes_lt_1ms":743,"mutex_wait_us":2453,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:17:38.452277 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:38.511051 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.059s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25078,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.511706 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:38.530431 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6980,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.530989 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:38.717801 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.187s	user 0.134s	sys 0.048s 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":275,"lbm_read_time_us":14544,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33558,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:17:38.718464 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=11.118625
I20260812 06:17:38.774762 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.056s	user 0.032s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":25017,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:38.775452 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:38.799863 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.024s	user 0.012s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6726,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:17:38.800501 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:38.979758 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.179s	user 0.098s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2584,"lbm_read_time_us":11658,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24360,"lbm_writes_lt_1ms":443,"mutex_wait_us":649,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:38.980407 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=10.126437
I20260812 06:17:39.038110 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.057s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20220,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:39.038658 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:39.050805 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.051316 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:39.204569 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.153s	user 0.106s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":10051,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23926,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:39.205453 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=10.126437
I20260812 06:17:39.264967 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.059s	user 0.041s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21275,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:39.265733 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:39.285343 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.286063 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:39.437274 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.151s	user 0.134s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1629,"lbm_read_time_us":14418,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26550,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.437832 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=11.118625
I20260812 06:17:39.482105 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16153,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.482729 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:39.497958 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5450,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.498600 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:39.650916 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.152s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":429,"lbm_read_time_us":9140,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25467,"lbm_writes_lt_1ms":443,"mutex_wait_us":158,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.651932 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=11.118625
I20260812 06:17:39.689920 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.038s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15497,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.690507 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:39.713683 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.023s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6139,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.714207 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:39.725407 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.726047 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushMRSOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:39.774708 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushMRSOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.048s	user 0.024s	sys 0.008s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":1636,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1700,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:39.775499 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling LogGCOp(195637cc0b70438fb979da387ab39e5c): free 112239272 bytes of WAL
I20260812 06:17:39.775815 15845 log_reader.cc:385] T 195637cc0b70438fb979da387ab39e5c: removed 11 log segments from log reader
I20260812 06:17:39.775862 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000015 (ops 70-74)
I20260812 06:17:39.775892 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000016 (ops 75-79)
I20260812 06:17:39.775935 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000017 (ops 80-84)
I20260812 06:17:39.775980 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000018 (ops 85-88)
I20260812 06:17:39.776011 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000019 (ops 89-93)
I20260812 06:17:39.776067 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000020 (ops 94-98)
I20260812 06:17:39.776109 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000021 (ops 99-103)
I20260812 06:17:39.776155 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000022 (ops 104-108)
I20260812 06:17:39.776192 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000023 (ops 109-113)
I20260812 06:17:39.776229 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000024 (ops 114-118)
I20260812 06:17:39.776265 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000025 (ops 119-123)
I20260812 06:17:39.802811 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: LogGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:39.803256 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=3.181125
I20260812 06:17:39.832317 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.029s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4802,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:39.832859 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c): 447 bytes on disk
I20260812 06:17:39.833302 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.833810 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:39.844444 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3913,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.844959 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:40.073182 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.228s	user 0.162s	sys 0.065s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1194,"lbm_read_time_us":16544,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41624,"lbm_writes_lt_1ms":743,"mutex_wait_us":547,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":94,"threads_started":1,"update_count":3500}
I20260812 06:17:40.074060 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:40.122620 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.048s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20771,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.123220 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:40.139489 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.140084 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:40.317332 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.177s	user 0.143s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":745,"lbm_read_time_us":13041,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31851,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:40.317977 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:40.370606 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.052s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23338,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.371250 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:40.385464 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.385977 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:40.559010 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.173s	user 0.121s	sys 0.052s 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":679,"lbm_read_time_us":13688,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30154,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2500}
I20260812 06:17:40.559876 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:40.617882 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.058s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20825,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.618531 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:40.629772 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.630296 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:40.822012 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.192s	user 0.123s	sys 0.056s 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":998,"lbm_read_time_us":13936,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30318,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:17:40.822861 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:40.878823 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.056s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22860,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.879331 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:40.900274 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.021s	user 0.013s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.901005 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:41.093977 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.193s	user 0.116s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":14246,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30252,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2500}
I20260812 06:17:41.094756 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:41.151036 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.056s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23829,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.151714 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:41.163470 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.164047 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:41.368983 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.205s	user 0.155s	sys 0.033s 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":187,"lbm_read_time_us":11068,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31908,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:41.369652 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:41.424499 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.055s	user 0.019s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23813,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.425076 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=2.188937
I20260812 06:17:41.437211 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4097,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.437788 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushMRSOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:41.473266 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushMRSOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1598,"drs_written":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1811,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:41.473981 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling LogGCOp(195637cc0b70438fb979da387ab39e5c): free 133024675 bytes of WAL
I20260812 06:17:41.474242 15845 log_reader.cc:385] T 195637cc0b70438fb979da387ab39e5c: removed 13 log segments from log reader
I20260812 06:17:41.474291 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000026 (ops 124-128)
I20260812 06:17:41.474321 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000027 (ops 129-132)
I20260812 06:17:41.474390 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000028 (ops 133-137)
I20260812 06:17:41.474433 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000029 (ops 138-142)
I20260812 06:17:41.474480 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000030 (ops 143-147)
I20260812 06:17:41.474546 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000031 (ops 148-152)
I20260812 06:17:41.474587 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000032 (ops 153-157)
I20260812 06:17:41.474630 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000033 (ops 158-162)
I20260812 06:17:41.474673 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000034 (ops 163-167)
I20260812 06:17:41.474712 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000035 (ops 168-172)
I20260812 06:17:41.474752 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000036 (ops 173-177)
I20260812 06:17:41.474790 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000037 (ops 178-182)
I20260812 06:17:41.474831 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000038 (ops 183-187)
I20260812 06:17:41.508733 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: LogGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:41.509219 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c): 493 bytes on disk
I20260812 06:17:41.509668 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: UndoDeltaBlockGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.510232 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=4.173312
I20260812 06:17:41.525509 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5948757,"delete_count":0,"lbm_write_time_us":6261,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:17:41.526031 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling LogGCOp(195637cc0b70438fb979da387ab39e5c): free 12017952 bytes of WAL
I20260812 06:17:41.526258 15845 log_reader.cc:385] T 195637cc0b70438fb979da387ab39e5c: removed 1 log segments from log reader
I20260812 06:17:41.526305 15845 log.cc:1079] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/195637cc0b70438fb979da387ab39e5c/wal-000000039 (ops 188-192)
I20260812 06:17:41.528750 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: LogGCOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:41.529101 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=1.196750
I20260812 06:17:41.537793 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.009s	user 0.005s	sys 0.001s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":2421,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:17:41.538501 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:41.720942 15677 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.258s	user 1.880s	sys 0.140s
I20260812 06:17:41.758232 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.220s	user 0.154s	sys 0.062s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979711,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15570,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39878,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:17:41.758946 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c): perf score=14.095187
I20260812 06:17:41.795173 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: FlushDeltaMemStoresOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17404,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:41.795970 15941 maintenance_manager.cc:419] P 4f655ca64650417b9a20ba7f43409c98: Scheduling MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c): perf score=1.000000
I20260812 06:17:41.832964 15677 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.111s	user 0.003s	sys 0.000s
I20260812 06:17:41.834874 15677 tablet_server.cc:179] TabletServer@127.15.79.65:0 shutting down...
I20260812 06:17:41.922751 15845 maintenance_manager.cc:643] P 4f655ca64650417b9a20ba7f43409c98: MajorDeltaCompactionOp(195637cc0b70438fb979da387ab39e5c) complete. Timing: real 0.127s	user 0.089s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":433,"lbm_read_time_us":11403,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23340,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:41.923563 15677 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:41.924015 15677 tablet_replica.cc:333] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98: stopping tablet replica
I20260812 06:17:41.924284 15677 raft_consensus.cc:2243] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:41.924557 15677 raft_consensus.cc:2272] T 195637cc0b70438fb979da387ab39e5c P 4f655ca64650417b9a20ba7f43409c98 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:41.942373 15677 tablet_server.cc:196] TabletServer@127.15.79.65:0 shutdown complete.
I20260812 06:17:41.962777 15677 master.cc:562] Master@127.15.79.126:33409 shutting down...
I20260812 06:17:41.967460 15677 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:41.967738 15677 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:41.967836 15677 tablet_replica.cc:333] T 00000000000000000000000000000000 P 766ab0f02a0945ac8113ba4b6204f9bd: stopping tablet replica
I20260812 06:17:41.981233 15677 master.cc:584] Master@127.15.79.126:33409 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5903 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:42.075289 15677 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.79.126:41385
I20260812 06:17:42.075798 15677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:42.078342 15990 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:42.078356 15677 server_base.cc:1061] running on GCE node
W20260812 06:17:42.078293 15988 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:42.078293 15992 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:42.078799 15677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:42.078848 15677 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:42.078866 15677 hybrid_clock.cc:648] HybridClock initialized: now 1786515462078866 us; error 0 us; skew 500 ppm
I20260812 06:17:42.079883 15677 webserver.cc:533] Webserver started at http://127.15.79.126:35171/ using document root <none> and password file <none>
I20260812 06:17:42.080049 15677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:42.080101 15677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:42.080158 15677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:42.080555 15677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/master-0-root/instance:
uuid: "e520809a67ad404dbe33931de368b751"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-sb2z"
I20260812 06:17:42.082093 15677 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:42.083148 16001 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:42.083411 15677 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:42.083544 15677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/master-0-root
uuid: "e520809a67ad404dbe33931de368b751"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-sb2z"
I20260812 06:17:42.083748 15677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-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:42.101133 15677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:42.101603 15677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:42.106144 15677 rpc_server.cc:307] RPC server started. Bound to: 127.15.79.126:41385
I20260812 06:17:42.119050 16095 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:42.125280 16094 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.79.126:41385 every 8 connection(s)
I20260812 06:17:42.126789 16095 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751: Bootstrap starting.
I20260812 06:17:42.127761 16095 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:42.128957 16095 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751: No bootstrap required, opened a new log
I20260812 06:17:42.129390 16095 raft_consensus.cc:359] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e520809a67ad404dbe33931de368b751" member_type: VOTER }
I20260812 06:17:42.129508 16095 raft_consensus.cc:385] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:42.129558 16095 raft_consensus.cc:740] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e520809a67ad404dbe33931de368b751, State: Initialized, Role: FOLLOWER
I20260812 06:17:42.129736 16095 consensus_queue.cc:260] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [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: "e520809a67ad404dbe33931de368b751" member_type: VOTER }
I20260812 06:17:42.129834 16095 raft_consensus.cc:399] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:42.129884 16095 raft_consensus.cc:493] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:42.129941 16095 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:42.130656 16095 raft_consensus.cc:515] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e520809a67ad404dbe33931de368b751" member_type: VOTER }
I20260812 06:17:42.130820 16095 leader_election.cc:304] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [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: e520809a67ad404dbe33931de368b751; no voters: 
I20260812 06:17:42.131038 16095 leader_election.cc:290] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:42.131191 16099 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:42.131425 16099 raft_consensus.cc:697] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 1 LEADER]: Becoming Leader. State: Replica: e520809a67ad404dbe33931de368b751, State: Running, Role: LEADER
I20260812 06:17:42.131592 16095 sys_catalog.cc:565] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:42.131613 16099 consensus_queue.cc:237] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [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: "e520809a67ad404dbe33931de368b751" member_type: VOTER }
I20260812 06:17:42.132135 16100 sys_catalog.cc:455] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e520809a67ad404dbe33931de368b751" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e520809a67ad404dbe33931de368b751" member_type: VOTER } }
I20260812 06:17:42.132157 16103 sys_catalog.cc:455] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e520809a67ad404dbe33931de368b751. Latest consensus state: current_term: 1 leader_uuid: "e520809a67ad404dbe33931de368b751" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e520809a67ad404dbe33931de368b751" member_type: VOTER } }
I20260812 06:17:42.132252 16100 sys_catalog.cc:458] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:42.132261 16103 sys_catalog.cc:458] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:42.132820 16110 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:42.133535 16110 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:42.133742 15677 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:42.135510 16110 catalog_manager.cc:1383] Generated new cluster ID: d114d2d0da43400aa9c7b68118d33e78
I20260812 06:17:42.135635 16110 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:42.156862 16110 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:42.157472 16110 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:42.168160 16110 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751: Generated new TSK 0
I20260812 06:17:42.168342 16110 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:42.198768 15677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:42.201261 16126 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:42.201297 15677 server_base.cc:1061] running on GCE node
W20260812 06:17:42.201228 16128 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:42.201248 16130 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:42.201747 15677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:42.201817 15677 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:42.201844 15677 hybrid_clock.cc:648] HybridClock initialized: now 1786515462201843 us; error 0 us; skew 500 ppm
I20260812 06:17:42.202754 15677 webserver.cc:533] Webserver started at http://127.15.79.65:33463/ using document root <none> and password file <none>
I20260812 06:17:42.202951 15677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:42.203027 15677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:42.203116 15677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:42.203626 15677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/instance:
uuid: "65e1bcc43ff24ec2accb63df5030d947"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-sb2z"
I20260812 06:17:42.205267 15677 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:42.206461 16138 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:42.206848 15677 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:42.206947 15677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root
uuid: "65e1bcc43ff24ec2accb63df5030d947"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-sb2z"
I20260812 06:17:42.207042 15677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-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:42.226466 15677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:42.226943 15677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:42.227308 15677 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:42.227875 15677 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:42.227942 15677 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:42.227995 15677 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:42.228045 15677 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:42.232420 15677 rpc_server.cc:307] RPC server started. Bound to: 127.15.79.65:46667
I20260812 06:17:42.232460 16239 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.79.65:46667 every 8 connection(s)
I20260812 06:17:42.241320 16240 heartbeater.cc:344] Connected to a master server at 127.15.79.126:41385
I20260812 06:17:42.241496 16240 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:42.241782 16240 heartbeater.cc:507] Master 127.15.79.126:41385 requested a full tablet report, sending...
I20260812 06:17:42.242517 16030 ts_manager.cc:194] Registered new tserver with Master: 65e1bcc43ff24ec2accb63df5030d947 (127.15.79.65:46667)
I20260812 06:17:42.242961 15677 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010074515s
I20260812 06:17:42.243395 16030 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44894
I20260812 06:17:42.250715 16030 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44908:
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:42.260381 16191 tablet_service.cc:1511] Processing CreateTablet for tablet 8c0be174e4f84fbe84ca898810ea4c75 (DEFAULT_TABLE table=heavy-update-compaction-test [id=398012466ab04a43af8f861461bec5cd]), partition=
I20260812 06:17:42.260730 16191 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8c0be174e4f84fbe84ca898810ea4c75. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:42.262864 16260 tablet_bootstrap.cc:492] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Bootstrap starting.
I20260812 06:17:42.263852 16260 tablet_bootstrap.cc:654] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:42.265136 16260 tablet_bootstrap.cc:492] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: No bootstrap required, opened a new log
I20260812 06:17:42.265281 16260 ts_tablet_manager.cc:1403] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:42.265758 16260 raft_consensus.cc:359] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65e1bcc43ff24ec2accb63df5030d947" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 46667 } }
I20260812 06:17:42.265878 16260 raft_consensus.cc:385] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:42.265944 16260 raft_consensus.cc:740] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 65e1bcc43ff24ec2accb63df5030d947, State: Initialized, Role: FOLLOWER
I20260812 06:17:42.266148 16260 consensus_queue.cc:260] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [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: "65e1bcc43ff24ec2accb63df5030d947" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 46667 } }
I20260812 06:17:42.266263 16260 raft_consensus.cc:399] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:42.266309 16260 raft_consensus.cc:493] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:42.266366 16260 raft_consensus.cc:3060] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:42.267149 16260 raft_consensus.cc:515] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65e1bcc43ff24ec2accb63df5030d947" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 46667 } }
I20260812 06:17:42.267321 16260 leader_election.cc:304] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [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: 65e1bcc43ff24ec2accb63df5030d947; no voters: 
I20260812 06:17:42.267581 16260 leader_election.cc:290] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:42.267727 16264 raft_consensus.cc:2804] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:42.267985 16260 ts_tablet_manager.cc:1434] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:42.268020 16240 heartbeater.cc:499] Master 127.15.79.126:41385 was elected leader, sending a full tablet report...
I20260812 06:17:42.268045 16264 raft_consensus.cc:697] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 1 LEADER]: Becoming Leader. State: Replica: 65e1bcc43ff24ec2accb63df5030d947, State: Running, Role: LEADER
I20260812 06:17:42.268234 16264 consensus_queue.cc:237] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [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: "65e1bcc43ff24ec2accb63df5030d947" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 46667 } }
I20260812 06:17:42.269702 16030 catalog_manager.cc:5719] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 reported cstate change: term changed from 0 to 1, leader changed from <none> to 65e1bcc43ff24ec2accb63df5030d947 (127.15.79.65). New cstate: current_term: 1 leader_uuid: "65e1bcc43ff24ec2accb63df5030d947" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65e1bcc43ff24ec2accb63df5030d947" member_type: VOTER last_known_addr { host: "127.15.79.65" port: 46667 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:42.332335 15677 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.019s	sys 0.004s
I20260812 06:17:42.483609 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=19.054940
I20260812 06:17:42.630281 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.146s	user 0.107s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":805,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37599,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:42.631268 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling LogGCOp(8c0be174e4f84fbe84ca898810ea4c75): free 20290830 bytes of WAL
I20260812 06:17:42.631698 16147 log_reader.cc:385] T 8c0be174e4f84fbe84ca898810ea4c75: removed 2 log segments from log reader
I20260812 06:17:42.631765 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000001 (ops 1-6)
I20260812 06:17:42.631816 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000002 (ops 7-10)
I20260812 06:17:42.637882 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: LogGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:42.638406 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:42.662554 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.024s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.663189 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:42.683439 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.020s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.684223 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75): 16411391 bytes on disk
I20260812 06:17:42.684890 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.685473 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:42.879424 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.194s	user 0.118s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":639,"lbm_read_time_us":11869,"lbm_reads_lt_1ms":569,"lbm_write_time_us":35043,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":42496,"thread_start_us":380,"threads_started":5,"update_count":2500}
I20260812 06:17:42.880111 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:42.938103 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.058s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26438,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.938712 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:42.963819 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.964341 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:43.167232 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.203s	user 0.123s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1442,"lbm_read_time_us":14576,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31400,"lbm_writes_lt_1ms":543,"mutex_wait_us":353,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:17:43.168001 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:43.211908 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.043s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18975,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.212498 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:43.229166 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.229651 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:43.412328 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.182s	user 0.126s	sys 0.053s 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":991,"lbm_read_time_us":10228,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35441,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:43.413013 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:43.466460 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.053s	user 0.036s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20331,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.466971 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:43.479104 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.479773 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:43.636518 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.157s	user 0.099s	sys 0.054s 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":511,"lbm_read_time_us":12162,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29383,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:43.637184 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=11.118625
I20260812 06:17:43.673691 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16031,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.674516 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:43.700438 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.026s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4977,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.700943 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:43.712225 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.712888 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:43.860427 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.147s	user 0.107s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":102,"lbm_read_time_us":10714,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30561,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:17:43.861212 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=10.126437
I20260812 06:17:43.905488 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19394,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.906046 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:43.917061 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.917615 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:43.951472 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1393,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2208,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:43.952260 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling LogGCOp(8c0be174e4f84fbe84ca898810ea4c75): free 121006423 bytes of WAL
I20260812 06:17:43.952512 16147 log_reader.cc:385] T 8c0be174e4f84fbe84ca898810ea4c75: removed 12 log segments from log reader
I20260812 06:17:43.952556 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000003 (ops 11-15)
I20260812 06:17:43.952611 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000004 (ops 16-20)
I20260812 06:17:43.952661 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000005 (ops 21-25)
I20260812 06:17:43.952706 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000006 (ops 26-30)
I20260812 06:17:43.952749 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000007 (ops 31-35)
I20260812 06:17:43.952813 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000008 (ops 36-40)
I20260812 06:17:43.952855 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000009 (ops 41-45)
I20260812 06:17:43.952896 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000010 (ops 46-50)
I20260812 06:17:43.952937 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000011 (ops 51-54)
I20260812 06:17:43.952980 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000012 (ops 55-59)
I20260812 06:17:43.953022 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000013 (ops 60-64)
I20260812 06:17:43.953063 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000014 (ops 65-69)
I20260812 06:17:43.979454 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: LogGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.027s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:17:43.980052 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75): 462 bytes on disk
I20260812 06:17:43.980526 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.981032 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=3.181125
I20260812 06:17:43.993856 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4787,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:43.994405 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:44.009081 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5153,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.009653 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:44.183230 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.173s	user 0.121s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":521,"lbm_read_time_us":12284,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35336,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":38272,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:17:44.184000 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:44.233328 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.049s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21637,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.234017 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:44.247181 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.247802 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:44.425503 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.177s	user 0.104s	sys 0.062s 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":826,"lbm_read_time_us":12006,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31787,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:17:44.426249 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:44.481326 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.055s	user 0.030s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24489,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.481907 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:44.653942 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.172s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":873,"lbm_read_time_us":11355,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27373,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:17:44.654589 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:44.707382 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.053s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24221,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.707998 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:44.731384 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.023s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.732057 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:44.920560 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.188s	user 0.128s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":13975,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30654,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:44.921487 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:44.973201 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.052s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22946,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.973765 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:44.986812 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.987336 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:45.163064 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.176s	user 0.142s	sys 0.025s 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":803,"lbm_read_time_us":12416,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31664,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.163852 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:45.214529 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.050s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20845,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.215121 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:45.227017 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.227726 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:45.394685 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.167s	user 0.119s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":10925,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32982,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:17:45.395227 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=11.118625
I20260812 06:17:45.433378 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.038s	user 0.034s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16375,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:45.434201 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:45.461063 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.027s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5156,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.461617 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:45.477231 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.477880 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:45.511217 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.033s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1631,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1686,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:45.512125 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling LogGCOp(8c0be174e4f84fbe84ca898810ea4c75): free 124257248 bytes of WAL
I20260812 06:17:45.512424 16147 log_reader.cc:385] T 8c0be174e4f84fbe84ca898810ea4c75: removed 12 log segments from log reader
I20260812 06:17:45.512506 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000015 (ops 70-74)
I20260812 06:17:45.512573 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000016 (ops 75-78)
I20260812 06:17:45.512619 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000017 (ops 79-83)
I20260812 06:17:45.512660 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000018 (ops 84-88)
I20260812 06:17:45.512704 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000019 (ops 89-93)
I20260812 06:17:45.512748 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000020 (ops 94-98)
I20260812 06:17:45.512789 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000021 (ops 99-103)
I20260812 06:17:45.512830 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000022 (ops 104-108)
I20260812 06:17:45.512871 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000023 (ops 109-113)
I20260812 06:17:45.512912 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000024 (ops 114-118)
I20260812 06:17:45.512962 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000025 (ops 119-123)
I20260812 06:17:45.513003 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000026 (ops 124-128)
I20260812 06:17:45.546303 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: LogGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.034s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:45.546834 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=3.181125
I20260812 06:17:45.568382 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.021s	user 0.012s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8223,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:45.568959 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:45.593792 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.025s	user 0.009s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4421,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.594616 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:45.846935 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.252s	user 0.175s	sys 0.067s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":601,"lbm_read_time_us":16898,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41596,"lbm_writes_lt_1ms":743,"mutex_wait_us":286,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:17:45.847747 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75): 483 bytes on disk
I20260812 06:17:45.848296 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.848978 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=18.063937
I20260812 06:17:45.912623 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.064s	user 0.048s	sys 0.012s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":26578,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.913293 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:45.925730 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.926322 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:46.124524 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.198s	user 0.126s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":898,"lbm_read_time_us":14042,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34592,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":3000}
I20260812 06:17:46.125227 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:46.183173 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.058s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22107,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.183890 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:46.198289 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.199054 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:46.386595 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.187s	user 0.126s	sys 0.054s 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":874,"lbm_read_time_us":13424,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29602,"lbm_writes_lt_1ms":543,"mutex_wait_us":403,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:46.387305 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:46.450651 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.063s	user 0.020s	sys 0.040s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":24942,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.451349 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:46.470381 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.470934 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:46.638474 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.167s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1080,"lbm_read_time_us":10888,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28243,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:17:46.639297 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:46.700956 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.061s	user 0.033s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21988,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.701833 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:46.720679 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.019s	user 0.002s	sys 0.016s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.721369 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:46.906170 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.185s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":12004,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31954,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:17:46.906894 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=14.095187
I20260812 06:17:46.955278 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.048s	user 0.045s	sys 0.000s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21199,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.955852 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:46.975369 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.976017 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:47.006783 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushMRSOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":1425,"drs_written":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1455,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:47.007735 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling LogGCOp(8c0be174e4f84fbe84ca898810ea4c75): free 117302827 bytes of WAL
I20260812 06:17:47.008013 16147 log_reader.cc:385] T 8c0be174e4f84fbe84ca898810ea4c75: removed 12 log segments from log reader
I20260812 06:17:47.008087 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000027 (ops 129-133)
I20260812 06:17:47.008131 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000028 (ops 134-138)
I20260812 06:17:47.008167 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000029 (ops 139-143)
I20260812 06:17:47.008198 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000030 (ops 144-148)
I20260812 06:17:47.008227 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000031 (ops 149-152)
I20260812 06:17:47.008258 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000032 (ops 153-157)
I20260812 06:17:47.008293 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000033 (ops 158-162)
I20260812 06:17:47.008325 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000034 (ops 163-167)
I20260812 06:17:47.008354 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000035 (ops 168-172)
I20260812 06:17:47.008384 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000036 (ops 173-176)
I20260812 06:17:47.008414 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000037 (ops 177-181)
I20260812 06:17:47.008450 16147 log.cc:1079] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: Deleting log segment in path: /tmp/dist-test-taskjhgqHl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515456160716-15677-0/minicluster-data/ts-0-root/wals/8c0be174e4f84fbe84ca898810ea4c75/wal-000000038 (ops 182-186)
I20260812 06:17:47.040951 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: LogGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.033s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:47.041486 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:47.069664 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.028s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.070230 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:47.082441 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.083323 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75): 447 bytes on disk
I20260812 06:17:47.083954 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: UndoDeltaBlockGCOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.084712 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:47.339408 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.254s	user 0.197s	sys 0.057s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979753,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":435,"lbm_read_time_us":18726,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41926,"lbm_writes_lt_1ms":743,"mutex_wait_us":63,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23424,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:17:47.340255 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=18.063937
I20260812 06:17:47.406204 15677 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.074s	user 1.900s	sys 0.149s
I20260812 06:17:47.408679 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.068s	user 0.055s	sys 0.012s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":32437,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:47.409189 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=2.188937
I20260812 06:17:47.419236 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: FlushDeltaMemStoresOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:17:47.419773 16241 maintenance_manager.cc:419] P 65e1bcc43ff24ec2accb63df5030d947: Scheduling MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75): perf score=1.000000
I20260812 06:17:47.446072 15677 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.039s	user 0.001s	sys 0.000s
I20260812 06:17:47.446631 15677 tablet_server.cc:179] TabletServer@127.15.79.65:0 shutting down...
I20260812 06:17:47.578742 16147 maintenance_manager.cc:643] P 65e1bcc43ff24ec2accb63df5030d947: MajorDeltaCompactionOp(8c0be174e4f84fbe84ca898810ea4c75) complete. Timing: real 0.159s	user 0.110s	sys 0.049s Metrics: {"cfile_cache_hit":24,"cfile_cache_hit_bytes":3409912,"cfile_cache_miss":608,"cfile_cache_miss_bytes":25467191,"cfile_init":5,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":316,"lbm_read_time_us":10288,"lbm_reads_lt_1ms":628,"lbm_write_time_us":27913,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":59392,"update_count":3000}
I20260812 06:17:47.579701 15677 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:47.579937 15677 tablet_replica.cc:333] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947: stopping tablet replica
I20260812 06:17:47.580083 15677 raft_consensus.cc:2243] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:47.580271 15677 raft_consensus.cc:2272] T 8c0be174e4f84fbe84ca898810ea4c75 P 65e1bcc43ff24ec2accb63df5030d947 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:47.584738 15677 tablet_server.cc:196] TabletServer@127.15.79.65:0 shutdown complete.
I20260812 06:17:47.631279 15677 master.cc:562] Master@127.15.79.126:41385 shutting down...
I20260812 06:17:47.634807 15677 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:47.635015 15677 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:47.635109 15677 tablet_replica.cc:333] T 00000000000000000000000000000000 P e520809a67ad404dbe33931de368b751: stopping tablet replica
I20260812 06:17:47.647912 15677 master.cc:584] Master@127.15.79.126:41385 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5668 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11573 ms total)

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