[==========] 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:18:02.334411  4694 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.149.190:45741
I20260812 06:18:02.335425  4694 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:18:02.335987  4694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:02.342067  4712 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.342061  4694 server_base.cc:1061] running on GCE node
W20260812 06:18:02.342059  4709 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:18:02.342231  4707 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.342729  4694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.342819  4694 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:02.342849  4694 hybrid_clock.cc:648] HybridClock initialized: now 1786515482342847 us; error 0 us; skew 500 ppm
I20260812 06:18:02.344542  4694 webserver.cc:533] Webserver started at http://127.4.149.190:33043/ using document root <none> and password file <none>
I20260812 06:18:02.345031  4694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.345081  4694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.345264  4694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.346786  4694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/master-0-root/instance:
uuid: "fa7d2a1efa43459fa1b82ebae6216ba0"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-21b9"
I20260812 06:18:02.350072  4694 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:02.351981  4719 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.352893  4694 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:02.352998  4694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/master-0-root
uuid: "fa7d2a1efa43459fa1b82ebae6216ba0"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-21b9"
I20260812 06:18:02.353089  4694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:02.365702  4694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:02.366269  4694 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:18:02.366415  4694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:02.373523  4694 rpc_server.cc:307] RPC server started. Bound to: 127.4.149.190:45741
I20260812 06:18:02.373524  4810 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.149.190:45741 every 8 connection(s)
I20260812 06:18:02.375635  4811 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:02.381102  4811 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0: Bootstrap starting.
I20260812 06:18:02.383453  4811 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:02.384333  4811 log.cc:826] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:02.385994  4811 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0: No bootstrap required, opened a new log
I20260812 06:18:02.388777  4811 raft_consensus.cc:359] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa7d2a1efa43459fa1b82ebae6216ba0" member_type: VOTER }
I20260812 06:18:02.388934  4811 raft_consensus.cc:385] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:02.389005  4811 raft_consensus.cc:740] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fa7d2a1efa43459fa1b82ebae6216ba0, State: Initialized, Role: FOLLOWER
I20260812 06:18:02.389581  4811 consensus_queue.cc:260] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [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: "fa7d2a1efa43459fa1b82ebae6216ba0" member_type: VOTER }
I20260812 06:18:02.389729  4811 raft_consensus.cc:399] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:02.389791  4811 raft_consensus.cc:493] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:02.389914  4811 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:02.390645  4811 raft_consensus.cc:515] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa7d2a1efa43459fa1b82ebae6216ba0" member_type: VOTER }
I20260812 06:18:02.391052  4811 leader_election.cc:304] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [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: fa7d2a1efa43459fa1b82ebae6216ba0; no voters: 
I20260812 06:18:02.391343  4811 leader_election.cc:290] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:02.391460  4815 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:02.391687  4815 raft_consensus.cc:697] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 1 LEADER]: Becoming Leader. State: Replica: fa7d2a1efa43459fa1b82ebae6216ba0, State: Running, Role: LEADER
I20260812 06:18:02.392087  4815 consensus_queue.cc:237] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [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: "fa7d2a1efa43459fa1b82ebae6216ba0" member_type: VOTER }
I20260812 06:18:02.392251  4811 sys_catalog.cc:565] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:02.393918  4818 sys_catalog.cc:455] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fa7d2a1efa43459fa1b82ebae6216ba0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa7d2a1efa43459fa1b82ebae6216ba0" member_type: VOTER } }
I20260812 06:18:02.394071  4818 sys_catalog.cc:458] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:02.393918  4822 sys_catalog.cc:455] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader fa7d2a1efa43459fa1b82ebae6216ba0. Latest consensus state: current_term: 1 leader_uuid: "fa7d2a1efa43459fa1b82ebae6216ba0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa7d2a1efa43459fa1b82ebae6216ba0" member_type: VOTER } }
I20260812 06:18:02.394258  4822 sys_catalog.cc:458] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:02.394361  4694 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:02.394956  4846 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:02.396961  4846 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:02.401378  4846 catalog_manager.cc:1383] Generated new cluster ID: dd67331134bd4ae197c878ec937c104c
I20260812 06:18:02.401453  4846 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:02.422925  4846 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:02.424147  4846 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:02.437870  4846 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0: Generated new TSK 0
I20260812 06:18:02.438644  4846 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:02.459170  4694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:02.462047  4858 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:02.462123  4854 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:18:02.462081  4853 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.462360  4694 server_base.cc:1061] running on GCE node
I20260812 06:18:02.462576  4694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.462622  4694 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:02.462638  4694 hybrid_clock.cc:648] HybridClock initialized: now 1786515482462639 us; error 0 us; skew 500 ppm
I20260812 06:18:02.463610  4694 webserver.cc:533] Webserver started at http://127.4.149.129:44681/ using document root <none> and password file <none>
I20260812 06:18:02.463770  4694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.463822  4694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.463898  4694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.464264  4694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/instance:
uuid: "a8bd15ab0b224a3daf7998368c6ea609"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-21b9"
I20260812 06:18:02.465758  4694 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:02.466651  4865 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.466898  4694 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:02.466969  4694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root
uuid: "a8bd15ab0b224a3daf7998368c6ea609"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-21b9"
I20260812 06:18:02.467039  4694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:02.477300  4694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:02.477723  4694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:02.478180  4694 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:02.479064  4694 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:02.479120  4694 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.479169  4694 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:02.479200  4694 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.485536  4694 rpc_server.cc:307] RPC server started. Bound to: 127.4.149.129:39913
I20260812 06:18:02.485580  4981 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.149.129:39913 every 8 connection(s)
I20260812 06:18:02.498340  4983 heartbeater.cc:344] Connected to a master server at 127.4.149.190:45741
I20260812 06:18:02.498565  4983 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:02.498975  4983 heartbeater.cc:507] Master 127.4.149.190:45741 requested a full tablet report, sending...
I20260812 06:18:02.500336  4743 ts_manager.cc:194] Registered new tserver with Master: a8bd15ab0b224a3daf7998368c6ea609 (127.4.149.129:39913)
I20260812 06:18:02.500607  4694 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014475281s
I20260812 06:18:02.501451  4743 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36650
I20260812 06:18:02.509359  4743 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36656:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:02.522596  4925 tablet_service.cc:1511] Processing CreateTablet for tablet 748e1e5c5ceb461c8793e66363e354f5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f309af40fede4924894a41f10f37bf47]), partition=
I20260812 06:18:02.523075  4925 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 748e1e5c5ceb461c8793e66363e354f5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:02.525286  5010 tablet_bootstrap.cc:492] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Bootstrap starting.
I20260812 06:18:02.526356  5010 tablet_bootstrap.cc:654] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:02.527691  5010 tablet_bootstrap.cc:492] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: No bootstrap required, opened a new log
I20260812 06:18:02.527807  5010 ts_tablet_manager.cc:1403] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:02.528637  5010 raft_consensus.cc:359] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8bd15ab0b224a3daf7998368c6ea609" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 39913 } }
I20260812 06:18:02.528771  5010 raft_consensus.cc:385] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:02.528823  5010 raft_consensus.cc:740] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a8bd15ab0b224a3daf7998368c6ea609, State: Initialized, Role: FOLLOWER
I20260812 06:18:02.528962  5010 consensus_queue.cc:260] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [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: "a8bd15ab0b224a3daf7998368c6ea609" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 39913 } }
I20260812 06:18:02.529069  5010 raft_consensus.cc:399] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:02.529135  5010 raft_consensus.cc:493] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:02.529188  5010 raft_consensus.cc:3060] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:02.530143  5010 raft_consensus.cc:515] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8bd15ab0b224a3daf7998368c6ea609" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 39913 } }
I20260812 06:18:02.530298  5010 leader_election.cc:304] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [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: a8bd15ab0b224a3daf7998368c6ea609; no voters: 
I20260812 06:18:02.530519  5010 leader_election.cc:290] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:02.530634  5012 raft_consensus.cc:2804] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:02.530853  5010 ts_tablet_manager.cc:1434] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:02.531073  4983 heartbeater.cc:499] Master 127.4.149.190:45741 was elected leader, sending a full tablet report...
I20260812 06:18:02.530884  5012 raft_consensus.cc:697] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 1 LEADER]: Becoming Leader. State: Replica: a8bd15ab0b224a3daf7998368c6ea609, State: Running, Role: LEADER
I20260812 06:18:02.531414  5012 consensus_queue.cc:237] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [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: "a8bd15ab0b224a3daf7998368c6ea609" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 39913 } }
I20260812 06:18:02.533814  4743 catalog_manager.cc:5719] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 reported cstate change: term changed from 0 to 1, leader changed from <none> to a8bd15ab0b224a3daf7998368c6ea609 (127.4.149.129). New cstate: current_term: 1 leader_uuid: "a8bd15ab0b224a3daf7998368c6ea609" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8bd15ab0b224a3daf7998368c6ea609" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 39913 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:02.600811  4694 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.023s	sys 0.008s
I20260812 06:18:02.736600  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5): perf score=19.054940
I20260812 06:18:02.910115  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.173s	user 0.120s	sys 0.041s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":271,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1182,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40361,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":161,"threads_started":1,"update_count":1500}
I20260812 06:18:02.911343  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling LogGCOp(748e1e5c5ceb461c8793e66363e354f5): free 20743880 bytes of WAL
I20260812 06:18:02.911648  4874 log_reader.cc:385] T 748e1e5c5ceb461c8793e66363e354f5: removed 2 log segments from log reader
I20260812 06:18:02.911705  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000001 (ops 1-6)
I20260812 06:18:02.911753  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000002 (ops 7-11)
I20260812 06:18:02.917011  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: LogGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:02.917412  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5): 16411393 bytes on disk
I20260812 06:18:02.918008  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.918406  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:02.933833  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4496,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.934309  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:03.070056  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.136s	user 0.089s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":717,"lbm_read_time_us":7125,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25999,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":302,"threads_started":5,"update_count":2000}
I20260812 06:18:03.070658  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:03.110803  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.040s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16644,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.111331  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:03.126703  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.127224  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:03.241704  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.114s	user 0.093s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":831,"lbm_read_time_us":7611,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20929,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39552,"update_count":2000}
I20260812 06:18:03.242264  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:03.276373  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.034s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13332,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.276854  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:03.287158  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.287774  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:03.407694  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.120s	user 0.096s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":9133,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21939,"lbm_writes_lt_1ms":443,"mutex_wait_us":318,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:18:03.408178  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:03.455024  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.047s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12828,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.455636  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:03.466909  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.011s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.467517  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:03.610083  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.142s	user 0.109s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":389,"lbm_read_time_us":9734,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23429,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30336,"update_count":2000}
I20260812 06:18:03.610797  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:03.643599  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.033s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13402,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.644050  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:03.654636  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.655211  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:03.774005  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.119s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":383,"lbm_read_time_us":9354,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21356,"lbm_writes_lt_1ms":443,"mutex_wait_us":11,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.774498  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:03.811801  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.037s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13147,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.812269  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:03.827530  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.828078  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:03.945127  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.117s	user 0.086s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":984,"lbm_read_time_us":7581,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23158,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:03.945616  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:03.985157  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.039s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12897,"lbm_writes_lt_1ms":303,"mutex_wait_us":1107,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.985723  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:04.001102  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.001753  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:04.047160  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.045s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1487,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:04.048053  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling LogGCOp(748e1e5c5ceb461c8793e66363e354f5): free 112692367 bytes of WAL
I20260812 06:18:04.048300  4874 log_reader.cc:385] T 748e1e5c5ceb461c8793e66363e354f5: removed 11 log segments from log reader
I20260812 06:18:04.048362  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000003 (ops 12-16)
I20260812 06:18:04.048405  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000004 (ops 17-21)
I20260812 06:18:04.048442  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000005 (ops 22-26)
I20260812 06:18:04.048473  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000006 (ops 27-31)
I20260812 06:18:04.048502  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000007 (ops 32-36)
I20260812 06:18:04.048530  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000008 (ops 37-41)
I20260812 06:18:04.048559  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000009 (ops 42-46)
I20260812 06:18:04.048593  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000010 (ops 47-51)
I20260812 06:18:04.048624  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000011 (ops 52-56)
I20260812 06:18:04.048652  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000012 (ops 57-61)
I20260812 06:18:04.048679  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000013 (ops 62-66)
I20260812 06:18:04.073717  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: LogGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:04.074101  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=3.181125
I20260812 06:18:04.095942  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.022s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4620,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:04.096473  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5): 447 bytes on disk
I20260812 06:18:04.096956  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.097420  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:04.111526  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5326,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.111959  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:04.308879  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.197s	user 0.152s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":154,"lbm_read_time_us":14479,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33575,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:04.309397  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=14.095187
I20260812 06:18:04.347826  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.038s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.348398  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:04.492579  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.144s	user 0.120s	sys 0.024s 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":141,"lbm_read_time_us":10975,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24049,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:18:04.493279  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:04.521710  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.028s	user 0.014s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12162,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.522192  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:04.534905  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.535449  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:04.667394  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.132s	user 0.116s	sys 0.014s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":635,"lbm_read_time_us":9384,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23723,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:04.668025  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:04.711746  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.044s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13108,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.712190  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:04.722131  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.722728  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:04.837628  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.115s	user 0.092s	sys 0.022s 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":501,"lbm_read_time_us":8329,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20925,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.838201  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:04.871897  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.034s	user 0.012s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15385,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.872370  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:04.885589  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.886097  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:05.006772  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.120s	user 0.103s	sys 0.017s 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":1140,"lbm_read_time_us":7791,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23679,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:05.007359  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:05.048877  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.041s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15187,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.049443  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:05.060448  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.061277  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:05.203661  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.142s	user 0.090s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":11323,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21952,"lbm_writes_lt_1ms":443,"mutex_wait_us":17,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:18:05.204242  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:05.242144  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.038s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15649,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.242642  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:05.252722  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.253312  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:05.374369  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.121s	user 0.102s	sys 0.016s 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":568,"lbm_read_time_us":7649,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21511,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:18:05.375164  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:05.416673  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18284,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:05.417316  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:05.435374  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.435915  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:05.476943  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.041s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1197,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1543,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:05.477756  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5): 483 bytes on disk
I20260812 06:18:05.478188  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.478689  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=3.181125
I20260812 06:18:05.496021  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6509,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:05.496538  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling LogGCOp(748e1e5c5ceb461c8793e66363e354f5): free 124710298 bytes of WAL
I20260812 06:18:05.496809  4874 log_reader.cc:385] T 748e1e5c5ceb461c8793e66363e354f5: removed 12 log segments from log reader
I20260812 06:18:05.496867  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000014 (ops 67-71)
I20260812 06:18:05.496908  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000015 (ops 72-76)
I20260812 06:18:05.496939  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000016 (ops 77-81)
I20260812 06:18:05.496974  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000017 (ops 82-86)
I20260812 06:18:05.497013  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000018 (ops 87-91)
I20260812 06:18:05.497044  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000019 (ops 92-96)
I20260812 06:18:05.497076  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000020 (ops 97-101)
I20260812 06:18:05.497105  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000021 (ops 102-106)
I20260812 06:18:05.497134  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000022 (ops 107-111)
I20260812 06:18:05.497165  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000023 (ops 112-116)
I20260812 06:18:05.497195  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000024 (ops 117-121)
I20260812 06:18:05.497224  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000025 (ops 122-126)
I20260812 06:18:05.518326  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: LogGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:05.518838  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:05.538424  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5353,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.538995  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:05.549530  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.549978  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:05.734862  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.185s	user 0.149s	sys 0.036s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":566,"lbm_read_time_us":12235,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37180,"lbm_writes_lt_1ms":743,"mutex_wait_us":244,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:18:05.735332  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=14.095187
I20260812 06:18:05.788269  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.053s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23963,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.788901  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:05.813799  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.025s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.814483  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:05.982643  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.168s	user 0.119s	sys 0.048s 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":834,"lbm_read_time_us":12320,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28250,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:05.983186  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=14.095187
I20260812 06:18:06.028888  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.045s	user 0.024s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18254,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.029395  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.040544  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.041018  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:06.194010  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.153s	user 0.125s	sys 0.018s 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":269,"lbm_read_time_us":9238,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26825,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:06.194633  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=14.095187
I20260812 06:18:06.243021  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.048s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":19788,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.243575  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.258626  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.259387  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:06.402489  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.143s	user 0.106s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":817,"lbm_read_time_us":9183,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29120,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:06.403043  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=11.118625
I20260812 06:18:06.433492  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.030s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12648,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.433985  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.455506  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":5092,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:06.455933  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.465552  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:06.465996  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:06.605979  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.140s	user 0.108s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1084,"lbm_read_time_us":9256,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28162,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:06.607227  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=11.118625
I20260812 06:18:06.635851  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.028s	user 0.023s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12206,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.636382  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.648626  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.649248  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:06.767388  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.118s	user 0.096s	sys 0.022s 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":99,"lbm_read_time_us":8780,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22566,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":148608,"update_count":2000}
I20260812 06:18:06.767994  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=10.126437
I20260812 06:18:06.813858  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.046s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14116,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.814529  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.829751  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.830281  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:06.870872  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushMRSOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.040s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1190,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1369,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:06.871673  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling LogGCOp(748e1e5c5ceb461c8793e66363e354f5): free 132571583 bytes of WAL
I20260812 06:18:06.871912  4874 log_reader.cc:385] T 748e1e5c5ceb461c8793e66363e354f5: removed 13 log segments from log reader
I20260812 06:18:06.871974  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000026 (ops 127-131)
I20260812 06:18:06.872023  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000027 (ops 132-136)
I20260812 06:18:06.872056  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000028 (ops 137-141)
I20260812 06:18:06.872085  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000029 (ops 142-146)
I20260812 06:18:06.872113  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000030 (ops 147-151)
I20260812 06:18:06.872146  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000031 (ops 152-156)
I20260812 06:18:06.872179  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000032 (ops 157-160)
I20260812 06:18:06.872205  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000033 (ops 161-165)
I20260812 06:18:06.872232  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000034 (ops 166-170)
I20260812 06:18:06.872262  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000035 (ops 171-175)
I20260812 06:18:06.872294  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000036 (ops 176-180)
I20260812 06:18:06.872324  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000037 (ops 181-184)
I20260812 06:18:06.872352  4874 log.cc:1079] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/748e1e5c5ceb461c8793e66363e354f5/wal-000000038 (ops 185-189)
I20260812 06:18:06.899686  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: LogGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:06.900074  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=3.181125
I20260812 06:18:06.916354  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.016s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:06.916826  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=2.188937
I20260812 06:18:06.925953  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3190,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.926445  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:07.114984  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.188s	user 0.120s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":677,"lbm_read_time_us":11901,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31433,"lbm_writes_lt_1ms":643,"mutex_wait_us":311,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18304,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:07.115621  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5): perf score=14.095187
I20260812 06:18:07.155812  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: FlushDeltaMemStoresOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.040s	user 0.024s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.156328  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5): 472 bytes on disk
I20260812 06:18:07.156854  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: UndoDeltaBlockGCOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.157491  4986 maintenance_manager.cc:419] P a8bd15ab0b224a3daf7998368c6ea609: Scheduling MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5): perf score=1.000000
I20260812 06:18:07.181198  4694 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.580s	user 1.688s	sys 0.110s
I20260812 06:18:07.248595  4694 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.002s	sys 0.000s
I20260812 06:18:07.249233  4694 tablet_server.cc:179] TabletServer@127.4.149.129:0 shutting down...
I20260812 06:18:07.286854  4874 maintenance_manager.cc:643] P a8bd15ab0b224a3daf7998368c6ea609: MajorDeltaCompactionOp(748e1e5c5ceb461c8793e66363e354f5) complete. Timing: real 0.129s	user 0.083s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":308,"lbm_read_time_us":11418,"lbm_reads_lt_1ms":463,"lbm_write_time_us":19373,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:07.287636  4694 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:07.288028  4694 tablet_replica.cc:333] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609: stopping tablet replica
I20260812 06:18:07.288245  4694 raft_consensus.cc:2243] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.288457  4694 raft_consensus.cc:2272] T 748e1e5c5ceb461c8793e66363e354f5 P a8bd15ab0b224a3daf7998368c6ea609 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.304829  4694 tablet_server.cc:196] TabletServer@127.4.149.129:0 shutdown complete.
I20260812 06:18:07.325742  4694 master.cc:562] Master@127.4.149.190:45741 shutting down...
I20260812 06:18:07.329058  4694 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.329255  4694 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.329327  4694 tablet_replica.cc:333] T 00000000000000000000000000000000 P fa7d2a1efa43459fa1b82ebae6216ba0: stopping tablet replica
I20260812 06:18:07.341578  4694 master.cc:584] Master@127.4.149.190:45741 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5078 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:07.413209  4694 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.149.190:38869
I20260812 06:18:07.413604  4694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:07.415578  5048 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.415593  4694 server_base.cc:1061] running on GCE node
W20260812 06:18:07.415674  5042 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:18:07.415879  5040 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.416071  4694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:07.416113  4694 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:07.416127  4694 hybrid_clock.cc:648] HybridClock initialized: now 1786515487416128 us; error 0 us; skew 500 ppm
I20260812 06:18:07.416869  4694 webserver.cc:533] Webserver started at http://127.4.149.190:35793/ using document root <none> and password file <none>
I20260812 06:18:07.417002  4694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:07.417037  4694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:07.417092  4694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:07.417404  4694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/master-0-root/instance:
uuid: "0caa33f4981f47afbf4ef791fa59fb96"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-21b9"
I20260812 06:18:07.418816  4694 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:07.419696  5058 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.419906  4694 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:07.419971  4694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/master-0-root
uuid: "0caa33f4981f47afbf4ef791fa59fb96"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-21b9"
I20260812 06:18:07.420025  4694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:07.455150  4694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:07.455662  4694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:07.460041  4694 rpc_server.cc:307] RPC server started. Bound to: 127.4.149.190:38869
I20260812 06:18:07.473557  5150 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.149.190:38869 every 8 connection(s)
I20260812 06:18:07.474104  5152 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:07.476112  5152 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96: Bootstrap starting.
I20260812 06:18:07.476935  5152 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:07.478017  5152 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96: No bootstrap required, opened a new log
I20260812 06:18:07.478566  5152 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0caa33f4981f47afbf4ef791fa59fb96" member_type: VOTER }
I20260812 06:18:07.478668  5152 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:07.478691  5152 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0caa33f4981f47afbf4ef791fa59fb96, State: Initialized, Role: FOLLOWER
I20260812 06:18:07.478818  5152 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [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: "0caa33f4981f47afbf4ef791fa59fb96" member_type: VOTER }
I20260812 06:18:07.478901  5152 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:07.478927  5152 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:07.478961  5152 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:07.479702  5152 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0caa33f4981f47afbf4ef791fa59fb96" member_type: VOTER }
I20260812 06:18:07.479820  5152 leader_election.cc:304] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [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: 0caa33f4981f47afbf4ef791fa59fb96; no voters: 
I20260812 06:18:07.479969  5152 leader_election.cc:290] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:07.480094  5156 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:07.480298  5156 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 1 LEADER]: Becoming Leader. State: Replica: 0caa33f4981f47afbf4ef791fa59fb96, State: Running, Role: LEADER
I20260812 06:18:07.480356  5152 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:07.480463  5156 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [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: "0caa33f4981f47afbf4ef791fa59fb96" member_type: VOTER }
I20260812 06:18:07.480888  5159 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0caa33f4981f47afbf4ef791fa59fb96. Latest consensus state: current_term: 1 leader_uuid: "0caa33f4981f47afbf4ef791fa59fb96" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0caa33f4981f47afbf4ef791fa59fb96" member_type: VOTER } }
I20260812 06:18:07.480872  5157 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0caa33f4981f47afbf4ef791fa59fb96" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0caa33f4981f47afbf4ef791fa59fb96" member_type: VOTER } }
I20260812 06:18:07.480986  5159 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:07.480998  5157 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:07.481231  5166 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:07.482049  5166 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:07.482313  4694 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:07.483760  5166 catalog_manager.cc:1383] Generated new cluster ID: 5098c4069e7e4cff908275a65b4b4a8a
I20260812 06:18:07.483810  5166 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:07.496274  5166 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:07.496814  5166 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:07.514264  5166 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96: Generated new TSK 0
I20260812 06:18:07.514467  5166 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:07.546816  4694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:07.549052  5186 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.549099  4694 server_base.cc:1061] running on GCE node
W20260812 06:18:07.549127  5185 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:07.549080  5190 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.549533  4694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:07.549579  4694 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:07.549595  4694 hybrid_clock.cc:648] HybridClock initialized: now 1786515487549595 us; error 0 us; skew 500 ppm
I20260812 06:18:07.550432  4694 webserver.cc:533] Webserver started at http://127.4.149.129:33163/ using document root <none> and password file <none>
I20260812 06:18:07.550599  4694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:07.550652  4694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:07.550712  4694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:07.551098  4694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/instance:
uuid: "825ce99994174f9490556d8bfea9b31f"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-21b9"
I20260812 06:18:07.552575  4694 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:07.553445  5201 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.553690  4694 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:07.553758  4694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root
uuid: "825ce99994174f9490556d8bfea9b31f"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-21b9"
I20260812 06:18:07.553828  4694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:07.576748  4694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:07.577167  4694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:07.577483  4694 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:07.577958  4694 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:07.578009  4694 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.578056  4694 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:07.578085  4694 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.582448  4694 rpc_server.cc:307] RPC server started. Bound to: 127.4.149.129:35253
I20260812 06:18:07.582502  5321 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.149.129:35253 every 8 connection(s)
I20260812 06:18:07.590876  5322 heartbeater.cc:344] Connected to a master server at 127.4.149.190:38869
I20260812 06:18:07.591012  5322 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:07.591244  5322 heartbeater.cc:507] Master 127.4.149.190:38869 requested a full tablet report, sending...
I20260812 06:18:07.591943  5091 ts_manager.cc:194] Registered new tserver with Master: 825ce99994174f9490556d8bfea9b31f (127.4.149.129:35253)
I20260812 06:18:07.592680  5091 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33246
I20260812 06:18:07.592826  4694 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009980453s
I20260812 06:18:07.599834  5091 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33256:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:07.607820  5250 tablet_service.cc:1511] Processing CreateTablet for tablet 22eb8a821c3f469e8b3b51e54dccaa04 (DEFAULT_TABLE table=heavy-update-compaction-test [id=309ddda39d9f4576ae8c9c6a65480776]), partition=
I20260812 06:18:07.608088  5250 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 22eb8a821c3f469e8b3b51e54dccaa04. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:07.609966  5345 tablet_bootstrap.cc:492] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Bootstrap starting.
I20260812 06:18:07.610903  5345 tablet_bootstrap.cc:654] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:07.611996  5345 tablet_bootstrap.cc:492] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: No bootstrap required, opened a new log
I20260812 06:18:07.612073  5345 ts_tablet_manager.cc:1403] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:07.612490  5345 raft_consensus.cc:359] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "825ce99994174f9490556d8bfea9b31f" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 35253 } }
I20260812 06:18:07.612579  5345 raft_consensus.cc:385] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:07.612612  5345 raft_consensus.cc:740] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 825ce99994174f9490556d8bfea9b31f, State: Initialized, Role: FOLLOWER
I20260812 06:18:07.612740  5345 consensus_queue.cc:260] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [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: "825ce99994174f9490556d8bfea9b31f" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 35253 } }
I20260812 06:18:07.612813  5345 raft_consensus.cc:399] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:07.612849  5345 raft_consensus.cc:493] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:07.612900  5345 raft_consensus.cc:3060] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:07.613737  5345 raft_consensus.cc:515] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "825ce99994174f9490556d8bfea9b31f" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 35253 } }
I20260812 06:18:07.613878  5345 leader_election.cc:304] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [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: 825ce99994174f9490556d8bfea9b31f; no voters: 
I20260812 06:18:07.614064  5345 leader_election.cc:290] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:07.614169  5347 raft_consensus.cc:2804] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:07.614346  5345 ts_tablet_manager.cc:1434] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:07.614367  5347 raft_consensus.cc:697] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 1 LEADER]: Becoming Leader. State: Replica: 825ce99994174f9490556d8bfea9b31f, State: Running, Role: LEADER
I20260812 06:18:07.614368  5322 heartbeater.cc:499] Master 127.4.149.190:38869 was elected leader, sending a full tablet report...
I20260812 06:18:07.614549  5347 consensus_queue.cc:237] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [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: "825ce99994174f9490556d8bfea9b31f" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 35253 } }
I20260812 06:18:07.615756  5091 catalog_manager.cc:5719] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f reported cstate change: term changed from 0 to 1, leader changed from <none> to 825ce99994174f9490556d8bfea9b31f (127.4.149.129). New cstate: current_term: 1 leader_uuid: "825ce99994174f9490556d8bfea9b31f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "825ce99994174f9490556d8bfea9b31f" member_type: VOTER last_known_addr { host: "127.4.149.129" port: 35253 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:07.670606  4694 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.008s
I20260812 06:18:07.833287  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=23.023690
I20260812 06:18:07.987334  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.154s	user 0.111s	sys 0.041s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1065,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42517,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:07.988068  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04): free 20743880 bytes of WAL
I20260812 06:18:07.988301  5209 log_reader.cc:385] T 22eb8a821c3f469e8b3b51e54dccaa04: removed 2 log segments from log reader
I20260812 06:18:07.988368  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000001 (ops 1-6)
I20260812 06:18:07.988406  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000002 (ops 7-11)
I20260812 06:18:07.993577  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:07.994048  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:08.019394  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.025s	user 0.008s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.019825  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04): 20513811 bytes on disk
I20260812 06:18:08.020202  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04) 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:18:08.020697  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:08.177814  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.157s	user 0.091s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":11009,"lbm_reads_lt_1ms":460,"lbm_write_time_us":21684,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":308,"threads_started":5,"update_count":2000}
I20260812 06:18:08.178303  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=14.095187
I20260812 06:18:08.221274  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.043s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18388,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.221751  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:08.237020  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.238327  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:08.390167  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.152s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":9253,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28653,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34176,"update_count":2500}
I20260812 06:18:08.390712  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=11.118625
I20260812 06:18:08.421841  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.031s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":12748,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:08.422389  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:08.444568  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.022s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4994,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:08.445025  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:08.454952  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3747,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:18:08.455408  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:08.601620  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.146s	user 0.117s	sys 0.029s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":446,"lbm_read_time_us":10740,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27073,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:08.602160  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:08.640801  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.038s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15811,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.641253  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:08.651186  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.651700  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:08.772084  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.120s	user 0.096s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":8296,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23302,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:18:08.772733  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:08.819990  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.047s	user 0.026s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12896,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.820546  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:08.830883  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.831586  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:08.972554  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.141s	user 0.080s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":888,"lbm_read_time_us":10196,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21822,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:08.973166  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:09.028184  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.055s	user 0.024s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":30350,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.028707  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:09.038590  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.039290  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:09.162999  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.123s	user 0.090s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":752,"lbm_read_time_us":7989,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24378,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:09.163560  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:09.200222  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.037s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13114,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.200790  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:09.210662  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.211259  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:09.240077  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1182,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1496,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:09.240722  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04): free 121006436 bytes of WAL
I20260812 06:18:09.240983  5209 log_reader.cc:385] T 22eb8a821c3f469e8b3b51e54dccaa04: removed 12 log segments from log reader
I20260812 06:18:09.241034  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000003 (ops 12-16)
I20260812 06:18:09.241073  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000004 (ops 17-20)
I20260812 06:18:09.241106  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000005 (ops 21-25)
I20260812 06:18:09.241138  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000006 (ops 26-30)
I20260812 06:18:09.241168  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000007 (ops 31-35)
I20260812 06:18:09.241199  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000008 (ops 36-40)
I20260812 06:18:09.241230  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000009 (ops 41-45)
I20260812 06:18:09.241259  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000010 (ops 46-50)
I20260812 06:18:09.241288  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000011 (ops 51-55)
I20260812 06:18:09.241318  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000012 (ops 56-60)
I20260812 06:18:09.241348  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000013 (ops 61-65)
I20260812 06:18:09.241379  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000014 (ops 66-70)
I20260812 06:18:09.263175  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:09.263643  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=3.181125
I20260812 06:18:09.282917  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.019s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6475,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:09.283391  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04): free 11564875 bytes of WAL
I20260812 06:18:09.283594  5209 log_reader.cc:385] T 22eb8a821c3f469e8b3b51e54dccaa04: removed 1 log segments from log reader
I20260812 06:18:09.283641  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000015 (ops 71-74)
I20260812 06:18:09.285323  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:09.285658  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:09.294943  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3239,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.295696  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:09.459602  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.164s	user 0.109s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":379,"lbm_read_time_us":12268,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31733,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":604160,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:18:09.460251  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=14.095187
I20260812 06:18:09.507297  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.047s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18551,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.507859  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04): 472 bytes on disk
I20260812 06:18:09.508296  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.508787  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:09.518600  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.519161  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:09.664158  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.145s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":10407,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27981,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:18:09.664719  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=11.118625
I20260812 06:18:09.696640  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.032s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":13395,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:09.697207  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:09.712263  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5565,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.712803  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:09.836992  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.124s	user 0.093s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713262,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1168,"lbm_read_time_us":9862,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21072,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":2000}
I20260812 06:18:09.837574  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:09.874177  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.036s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.874663  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:09.885247  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.885844  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:10.003877  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.118s	user 0.082s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":317,"lbm_read_time_us":8238,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22900,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:10.004348  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:10.051522  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.047s	user 0.032s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15041,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.052184  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:10.063014  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.063580  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:10.216619  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.153s	user 0.101s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":9882,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24857,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2000}
I20260812 06:18:10.217139  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:10.260317  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.043s	user 0.023s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12284,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.260892  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:10.276568  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.277292  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:10.398653  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.121s	user 0.106s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":9723,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22213,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:10.399128  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:10.437220  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.038s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14189,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.437812  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:10.448495  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.449388  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:10.572098  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.123s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":143,"lbm_read_time_us":9149,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21097,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:10.572654  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:10.612285  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.039s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14165,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.612839  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:10.627930  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.628609  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:10.656723  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":155,"dirs.run_wall_time_us":1335,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1782,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:10.657372  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04): free 121006454 bytes of WAL
I20260812 06:18:10.657629  5209 log_reader.cc:385] T 22eb8a821c3f469e8b3b51e54dccaa04: removed 12 log segments from log reader
I20260812 06:18:10.657681  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000016 (ops 75-79)
I20260812 06:18:10.657720  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000017 (ops 80-84)
I20260812 06:18:10.657753  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000018 (ops 85-88)
I20260812 06:18:10.657785  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000019 (ops 89-93)
I20260812 06:18:10.657817  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000020 (ops 94-98)
I20260812 06:18:10.657847  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000021 (ops 99-103)
I20260812 06:18:10.657879  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000022 (ops 104-108)
I20260812 06:18:10.657910  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000023 (ops 109-113)
I20260812 06:18:10.657940  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000024 (ops 114-118)
I20260812 06:18:10.657986  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000025 (ops 119-123)
I20260812 06:18:10.658011  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000026 (ops 124-128)
I20260812 06:18:10.658042  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000027 (ops 129-133)
I20260812 06:18:10.679061  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:10.679471  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04): 483 bytes on disk
I20260812 06:18:10.679929  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.680548  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=3.181125
I20260812 06:18:10.698388  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6693,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:10.698802  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:10.707815  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3466,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.708274  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:10.877084  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.169s	user 0.126s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":163,"lbm_read_time_us":11270,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33618,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:10.879608  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=14.095187
I20260812 06:18:10.929412  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.050s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19018,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.929975  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:10.945863  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.946439  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:11.097325  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.151s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":501,"lbm_read_time_us":11160,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26768,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:18:11.097929  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=12.110812
I20260812 06:18:11.128590  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.030s	user 0.018s	sys 0.011s Metrics: {"bytes_written":13497196,"delete_count":0,"lbm_write_time_us":12540,"lbm_writes_lt_1ms":332,"reinsert_count":0,"update_count":1645}
I20260812 06:18:11.129248  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.196750
I20260812 06:18:11.142834  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":3733,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:18:11.143262  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:11.284659  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.141s	user 0.097s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":956,"lbm_read_time_us":8806,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21748,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:11.285164  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=14.095187
I20260812 06:18:11.333477  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21598,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.334103  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:11.352487  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.018s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.352998  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:11.519558  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.166s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":71,"lbm_read_time_us":11704,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28288,"lbm_writes_lt_1ms":543,"mutex_wait_us":17,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:18:11.520043  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:11.554461  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.034s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14809,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.555181  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:11.578199  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.578706  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:11.595899  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.596550  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:11.768446  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.172s	user 0.124s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815805,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1015,"lbm_read_time_us":9588,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27193,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:11.768942  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=14.095187
I20260812 06:18:11.818387  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.049s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18890,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.818929  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:11.829397  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.830083  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:11.978508  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.148s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1004,"lbm_read_time_us":10614,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26523,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:18:11.979110  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=10.126437
I20260812 06:18:12.014163  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.034s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14073,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.014819  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:12.028501  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.029134  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:12.066134  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushMRSOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.037s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1366,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1640,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:12.067095  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04): 482 bytes on disk
I20260812 06:18:12.067658  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: UndoDeltaBlockGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.068297  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=3.181125
I20260812 06:18:12.080379  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:12.080968  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04): free 128867676 bytes of WAL
I20260812 06:18:12.081207  5209 log_reader.cc:385] T 22eb8a821c3f469e8b3b51e54dccaa04: removed 13 log segments from log reader
I20260812 06:18:12.081275  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000028 (ops 134-138)
I20260812 06:18:12.081321  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000029 (ops 139-143)
I20260812 06:18:12.081358  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000030 (ops 144-148)
I20260812 06:18:12.081389  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000031 (ops 149-152)
I20260812 06:18:12.081418  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000032 (ops 153-157)
I20260812 06:18:12.081445  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000033 (ops 158-162)
I20260812 06:18:12.081475  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000034 (ops 163-166)
I20260812 06:18:12.081508  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000035 (ops 167-171)
I20260812 06:18:12.081538  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000036 (ops 172-176)
I20260812 06:18:12.081566  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000037 (ops 177-181)
I20260812 06:18:12.081593  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000038 (ops 182-186)
I20260812 06:18:12.081624  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000039 (ops 187-190)
I20260812 06:18:12.081655  5209 log.cc:1079] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: Deleting log segment in path: /tmp/dist-test-taskS7nQnh/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482324065-4694-0/minicluster-data/ts-0-root/wals/22eb8a821c3f469e8b3b51e54dccaa04/wal-000000040 (ops 191-195)
I20260812 06:18:12.108784  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: LogGCOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:12.109440  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:12.125120  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.016s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3386,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.125603  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=2.188937
I20260812 06:18:12.149971  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: FlushDeltaMemStoresOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.024s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.150604  5323 maintenance_manager.cc:419] P 825ce99994174f9490556d8bfea9b31f: Scheduling MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04): perf score=1.000000
I20260812 06:18:12.205716  4694 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.535s	user 1.680s	sys 0.131s
I20260812 06:18:12.317452  4694 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.111s	user 0.000s	sys 0.000s
I20260812 06:18:12.317951  4694 tablet_server.cc:179] TabletServer@127.4.149.129:0 shutting down...
I20260812 06:18:12.354303  5209 maintenance_manager.cc:643] P 825ce99994174f9490556d8bfea9b31f: MajorDeltaCompactionOp(22eb8a821c3f469e8b3b51e54dccaa04) complete. Timing: real 0.204s	user 0.131s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020851,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":825,"lbm_read_time_us":16037,"lbm_reads_lt_1ms":771,"lbm_write_time_us":30237,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18432,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:18:12.355329  4694 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:12.355715  4694 tablet_replica.cc:333] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f: stopping tablet replica
I20260812 06:18:12.355844  4694 raft_consensus.cc:2243] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:12.355988  4694 raft_consensus.cc:2272] T 22eb8a821c3f469e8b3b51e54dccaa04 P 825ce99994174f9490556d8bfea9b31f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:12.360132  4694 tablet_server.cc:196] TabletServer@127.4.149.129:0 shutdown complete.
I20260812 06:18:12.411356  4694 master.cc:562] Master@127.4.149.190:38869 shutting down...
I20260812 06:18:12.414026  4694 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:12.414201  4694 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:12.414252  4694 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0caa33f4981f47afbf4ef791fa59fb96: stopping tablet replica
I20260812 06:18:12.426471  4694 master.cc:584] Master@127.4.149.190:38869 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5080 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10160 ms total)

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