[==========] 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:20:28.233839 16980 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.149.62:39223
I20260812 06:20:28.235038 16980 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:20:28.235693 16980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.242705 16991 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:20:28.242699 16989 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:20:28.242873 16980 server_base.cc:1061] running on GCE node
W20260812 06:20:28.243018 16988 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:20:28.243582 16980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.243713 16980 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:20:28.243780 16980 hybrid_clock.cc:648] HybridClock initialized: now 1786515628243778 us; error 0 us; skew 500 ppm
I20260812 06:20:28.245976 16980 webserver.cc:533] Webserver started at http://127.16.149.62:41859/ using document root <none> and password file <none>
I20260812 06:20:28.246632 16980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.246726 16980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.246981 16980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.248816 16980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/master-0-root/instance:
uuid: "5b4433bfe503405fa066c7bd38f2b03a"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-6ntk"
I20260812 06:20:28.252852 16980 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.004s
I20260812 06:20:28.255200 16999 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:20:28.256290 16980 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:28.256429 16980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/master-0-root
uuid: "5b4433bfe503405fa066c7bd38f2b03a"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-6ntk"
I20260812 06:20:28.256541 16980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-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:20:28.268975 16980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.269734 16980 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:20:28.270018 16980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.279129 16980 rpc_server.cc:307] RPC server started. Bound to: 127.16.149.62:39223
I20260812 06:20:28.279196 17087 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.149.62:39223 every 8 connection(s)
I20260812 06:20:28.281960 17089 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:20:28.288316 17089 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: Bootstrap starting.
I20260812 06:20:28.291113 17089 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.292232 17089 log.cc:826] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:28.294512 17089 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: No bootstrap required, opened a new log
I20260812 06:20:28.297920 17089 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b4433bfe503405fa066c7bd38f2b03a" member_type: VOTER }
I20260812 06:20:28.298132 17089 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.298274 17089 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b4433bfe503405fa066c7bd38f2b03a, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.299039 17089 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [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: "5b4433bfe503405fa066c7bd38f2b03a" member_type: VOTER }
I20260812 06:20:28.299240 17089 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.299377 17089 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.299566 17089 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.300551 17089 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b4433bfe503405fa066c7bd38f2b03a" member_type: VOTER }
I20260812 06:20:28.301097 17089 leader_election.cc:304] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [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: 5b4433bfe503405fa066c7bd38f2b03a; no voters: 
I20260812 06:20:28.301555 17089 leader_election.cc:290] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.301767 17097 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.302086 17097 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 1 LEADER]: Becoming Leader. State: Replica: 5b4433bfe503405fa066c7bd38f2b03a, State: Running, Role: LEADER
I20260812 06:20:28.302587 17097 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [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: "5b4433bfe503405fa066c7bd38f2b03a" member_type: VOTER }
I20260812 06:20:28.302913 17089 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:28.304894 17099 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5b4433bfe503405fa066c7bd38f2b03a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b4433bfe503405fa066c7bd38f2b03a" member_type: VOTER } }
I20260812 06:20:28.305045 17099 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:28.305321 17100 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5b4433bfe503405fa066c7bd38f2b03a. Latest consensus state: current_term: 1 leader_uuid: "5b4433bfe503405fa066c7bd38f2b03a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b4433bfe503405fa066c7bd38f2b03a" member_type: VOTER } }
I20260812 06:20:28.305404 17100 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:28.305780 16980 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:28.307982 17119 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:28.308051 17119 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:28.308141 17116 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:28.308976 17116 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:28.314688 17116 catalog_manager.cc:1383] Generated new cluster ID: f2016151f1fe4bd3acd74a7c86734410
I20260812 06:20:28.314782 17116 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:28.325158 17116 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:28.326437 17116 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:28.337569 17116 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: Generated new TSK 0
I20260812 06:20:28.338512 17116 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:28.371557 16980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.374825 17126 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:20:28.374948 17127 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:20:28.375181 17130 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:20:28.375460 16980 server_base.cc:1061] running on GCE node
I20260812 06:20:28.375698 16980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.375774 16980 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:20:28.375818 16980 hybrid_clock.cc:648] HybridClock initialized: now 1786515628375817 us; error 0 us; skew 500 ppm
I20260812 06:20:28.377002 16980 webserver.cc:533] Webserver started at http://127.16.149.1:38795/ using document root <none> and password file <none>
I20260812 06:20:28.377230 16980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.377319 16980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.377415 16980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.377995 16980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/instance:
uuid: "5b2e31a210904f8e8d922652fb0cae3d"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-6ntk"
I20260812 06:20:28.379870 16980 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:28.381161 17144 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:20:28.381536 16980 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:28.381654 16980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root
uuid: "5b2e31a210904f8e8d922652fb0cae3d"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-6ntk"
I20260812 06:20:28.381758 16980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-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:20:28.396364 16980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.396948 16980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.397533 16980 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:28.398520 16980 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:28.398599 16980 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.398684 16980 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:28.398726 16980 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.406293 16980 rpc_server.cc:307] RPC server started. Bound to: 127.16.149.1:39807
I20260812 06:20:28.406318 17254 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.149.1:39807 every 8 connection(s)
I20260812 06:20:28.422072 17255 heartbeater.cc:344] Connected to a master server at 127.16.149.62:39223
I20260812 06:20:28.422400 17255 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:28.422978 17255 heartbeater.cc:507] Master 127.16.149.62:39223 requested a full tablet report, sending...
I20260812 06:20:28.424765 17031 ts_manager.cc:194] Registered new tserver with Master: 5b2e31a210904f8e8d922652fb0cae3d (127.16.149.1:39807)
I20260812 06:20:28.425074 16980 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018040237s
I20260812 06:20:28.426354 17031 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47246
I20260812 06:20:28.436357 17031 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47262:
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:20:28.454396 17193 tablet_service.cc:1511] Processing CreateTablet for tablet 697dde97a74b4e92ae9c241f117407e1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f9062548af95437eb45c2ef4f565a374]), partition=
I20260812 06:20:28.454914 17193 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 697dde97a74b4e92ae9c241f117407e1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:28.457301 17280 tablet_bootstrap.cc:492] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Bootstrap starting.
I20260812 06:20:28.459565 17280 tablet_bootstrap.cc:654] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.461371 17280 tablet_bootstrap.cc:492] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: No bootstrap required, opened a new log
I20260812 06:20:28.461512 17280 ts_tablet_manager.cc:1403] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Time spent bootstrapping tablet: real 0.004s	user 0.000s	sys 0.003s
I20260812 06:20:28.462272 17280 raft_consensus.cc:359] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b2e31a210904f8e8d922652fb0cae3d" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 39807 } }
I20260812 06:20:28.462430 17280 raft_consensus.cc:385] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.462474 17280 raft_consensus.cc:740] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b2e31a210904f8e8d922652fb0cae3d, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.462634 17280 consensus_queue.cc:260] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [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: "5b2e31a210904f8e8d922652fb0cae3d" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 39807 } }
I20260812 06:20:28.462744 17280 raft_consensus.cc:399] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.462800 17280 raft_consensus.cc:493] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.462872 17280 raft_consensus.cc:3060] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.464109 17280 raft_consensus.cc:515] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b2e31a210904f8e8d922652fb0cae3d" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 39807 } }
I20260812 06:20:28.464289 17280 leader_election.cc:304] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [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: 5b2e31a210904f8e8d922652fb0cae3d; no voters: 
I20260812 06:20:28.464570 17280 leader_election.cc:290] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.464720 17285 raft_consensus.cc:2804] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.464982 17280 ts_tablet_manager.cc:1434] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:20:28.464979 17285 raft_consensus.cc:697] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 1 LEADER]: Becoming Leader. State: Replica: 5b2e31a210904f8e8d922652fb0cae3d, State: Running, Role: LEADER
I20260812 06:20:28.465197 17285 consensus_queue.cc:237] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [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: "5b2e31a210904f8e8d922652fb0cae3d" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 39807 } }
I20260812 06:20:28.465220 17255 heartbeater.cc:499] Master 127.16.149.62:39223 was elected leader, sending a full tablet report...
I20260812 06:20:28.468851 17031 catalog_manager.cc:5719] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b2e31a210904f8e8d922652fb0cae3d (127.16.149.1). New cstate: current_term: 1 leader_uuid: "5b2e31a210904f8e8d922652fb0cae3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b2e31a210904f8e8d922652fb0cae3d" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 39807 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:28.538970 16980 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.023s	sys 0.004s
I20260812 06:20:28.657748 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushMRSOp(697dde97a74b4e92ae9c241f117407e1): perf score=15.086190
I20260812 06:20:28.855690 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushMRSOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.197s	user 0.153s	sys 0.036s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":269,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":879,"drs_written":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46083,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":164,"threads_started":1,"update_count":1500}
I20260812 06:20:28.857023 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling LogGCOp(697dde97a74b4e92ae9c241f117407e1): free 8725963 bytes of WAL
I20260812 06:20:28.857452 17150 log_reader.cc:385] T 697dde97a74b4e92ae9c241f117407e1: removed 1 log segments from log reader
I20260812 06:20:28.857551 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000001 (ops 1-6)
I20260812 06:20:28.860227 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: LogGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:28.860991 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:28.880970 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.020s	user 0.016s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.881507 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:29.021971 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.140s	user 0.107s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":991,"lbm_read_time_us":8596,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27482,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":365,"threads_started":5,"update_count":2000}
I20260812 06:20:29.022645 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1): 12308959 bytes on disk
I20260812 06:20:29.023329 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:20:29.023954 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:29.068387 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.044s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":19364,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.068899 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:29.080425 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.081048 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:29.217742 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.136s	user 0.124s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631316,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":10720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27288,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:29.218393 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:29.268626 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.050s	user 0.010s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.269215 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:29.283394 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.014s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.284092 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:29.432737 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.148s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":12182,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28030,"lbm_writes_lt_1ms":443,"mutex_wait_us":105,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":36992,"update_count":2000}
I20260812 06:20:29.433452 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:29.494302 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.061s	user 0.032s	sys 0.019s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":18323,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.494905 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:29.507376 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.507944 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:29.669783 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.162s	user 0.102s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631316,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":12365,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26236,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:29.670508 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:29.718044 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.047s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19317,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.718578 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:29.729985 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.730542 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:29.851598 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.121s	user 0.104s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":168,"lbm_read_time_us":8691,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23645,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.852243 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:29.897560 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.045s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17056,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.898164 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:29.910436 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.910923 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:30.043267 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.132s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":10958,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25300,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2000}
I20260812 06:20:30.043922 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:30.091244 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.047s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16970,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.091831 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:30.108600 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.017s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.109308 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushMRSOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:30.138604 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushMRSOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":307,"dirs.run_wall_time_us":1572,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1766,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:30.139467 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling LogGCOp(697dde97a74b4e92ae9c241f117407e1): free 124257231 bytes of WAL
I20260812 06:20:30.139730 17150 log_reader.cc:385] T 697dde97a74b4e92ae9c241f117407e1: removed 12 log segments from log reader
I20260812 06:20:30.139778 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000002 (ops 7-11)
I20260812 06:20:30.139809 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000003 (ops 12-16)
I20260812 06:20:30.139866 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000004 (ops 17-21)
I20260812 06:20:30.139916 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000005 (ops 22-26)
I20260812 06:20:30.139961 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000006 (ops 27-31)
I20260812 06:20:30.140002 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000007 (ops 32-36)
I20260812 06:20:30.140064 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000008 (ops 37-40)
I20260812 06:20:30.140100 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000009 (ops 41-45)
I20260812 06:20:30.140156 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000010 (ops 46-50)
I20260812 06:20:30.140194 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000011 (ops 51-55)
I20260812 06:20:30.140240 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000012 (ops 56-60)
I20260812 06:20:30.140277 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000013 (ops 61-65)
I20260812 06:20:30.170661 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: LogGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:30.171106 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1): 448 bytes on disk
I20260812 06:20:30.171574 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:30.172195 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=3.181125
I20260812 06:20:30.185652 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4676998,"delete_count":0,"lbm_write_time_us":5120,"lbm_writes_lt_1ms":117,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":570}
I20260812 06:20:30.186244 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:30.201975 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":5816,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:20:30.202451 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:30.387902 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.185s	user 0.127s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836362,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":285,"lbm_read_time_us":11957,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38347,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16512,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:20:30.388747 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=14.095187
I20260812 06:20:30.446372 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.057s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24134,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.446923 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:30.461205 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.014s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.461720 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:30.640640 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.179s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":356,"lbm_read_time_us":13593,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33981,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:20:30.641311 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=14.095187
I20260812 06:20:30.699863 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.058s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21468,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.700340 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:30.711452 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.712133 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:30.898615 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.186s	user 0.135s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":364,"lbm_read_time_us":13964,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29801,"lbm_writes_lt_1ms":543,"mutex_wait_us":138,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:30.899356 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=14.095187
I20260812 06:20:30.957676 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.058s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25169,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.958302 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:31.100519 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.142s	user 0.077s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1950,"lbm_read_time_us":10486,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24225,"lbm_writes_lt_1ms":443,"mutex_wait_us":621,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.101222 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:31.148195 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.047s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20399,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:31.148731 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:31.173741 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.174265 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:31.185150 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.185863 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:31.388818 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.203s	user 0.128s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":303,"lbm_read_time_us":12342,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32903,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:31.389621 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=14.095187
I20260812 06:20:31.446877 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.057s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28077,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.447414 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:31.460287 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.460968 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:31.624943 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.164s	user 0.126s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":530,"lbm_read_time_us":11806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30223,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":37888,"update_count":2500}
I20260812 06:20:31.625753 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=14.095187
I20260812 06:20:31.684172 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.058s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24171,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.684741 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:31.705483 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.021s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.706125 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushMRSOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:31.760021 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushMRSOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.054s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1810,"drs_written":1,"lbm_read_time_us":130,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1841,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:31.761119 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling LogGCOp(697dde97a74b4e92ae9c241f117407e1): free 120553390 bytes of WAL
I20260812 06:20:31.761379 17150 log_reader.cc:385] T 697dde97a74b4e92ae9c241f117407e1: removed 12 log segments from log reader
I20260812 06:20:31.761426 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000014 (ops 66-70)
I20260812 06:20:31.761461 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000015 (ops 71-75)
I20260812 06:20:31.761538 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000016 (ops 76-80)
I20260812 06:20:31.761585 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000017 (ops 81-84)
I20260812 06:20:31.761653 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000018 (ops 85-89)
I20260812 06:20:31.761698 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000019 (ops 90-94)
I20260812 06:20:31.761745 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000020 (ops 95-99)
I20260812 06:20:31.761801 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000021 (ops 100-104)
I20260812 06:20:31.761862 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000022 (ops 105-109)
I20260812 06:20:31.761933 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000023 (ops 110-114)
I20260812 06:20:31.761968 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000024 (ops 115-118)
I20260812 06:20:31.762009 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000025 (ops 119-123)
I20260812 06:20:31.794054 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: LogGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.033s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:20:31.797171 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=6.157687
I20260812 06:20:31.830444 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14398,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:31.831014 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling LogGCOp(697dde97a74b4e92ae9c241f117407e1): free 8767123 bytes of WAL
I20260812 06:20:31.831255 17150 log_reader.cc:385] T 697dde97a74b4e92ae9c241f117407e1: removed 1 log segments from log reader
I20260812 06:20:31.831331 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000026 (ops 124-128)
I20260812 06:20:31.833420 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: LogGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:31.833755 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1): 492 bytes on disk
I20260812 06:20:31.834211 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.834769 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:31.849021 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.849560 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:32.144119 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.294s	user 0.170s	sys 0.100s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37041198,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":786,"lbm_read_time_us":19056,"lbm_reads_lt_1ms":874,"lbm_write_time_us":50860,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":842,"mutex_wait_us":50,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":416,"threads_started":6,"update_count":4000}
I20260812 06:20:32.144872 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=22.032687
I20260812 06:20:32.221963 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.077s	user 0.037s	sys 0.040s Metrics: {"bytes_written":24614725,"delete_count":0,"lbm_write_time_us":34754,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:20:32.222635 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:32.239042 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":500}
I20260812 06:20:32.239697 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:32.474062 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.234s	user 0.148s	sys 0.084s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32938547,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":778,"lbm_read_time_us":17493,"lbm_reads_lt_1ms":772,"lbm_write_time_us":41348,"lbm_writes_lt_1ms":743,"mutex_wait_us":456,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3500}
I20260812 06:20:32.474881 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=18.063937
I20260812 06:20:32.537467 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.062s	user 0.041s	sys 0.016s Metrics: {"bytes_written":20594360,"delete_count":0,"lbm_write_time_us":27089,"lbm_writes_lt_1ms":505,"reinsert_count":0,"update_count":2510}
I20260812 06:20:32.538036 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=3.181125
I20260812 06:20:32.555636 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":7120,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:20:32.556208 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:32.567956 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.569342 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:32.777314 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.208s	user 0.165s	sys 0.037s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":546,"lbm_read_time_us":15880,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42338,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":26240,"update_count":3500}
I20260812 06:20:32.777851 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=18.063937
I20260812 06:20:32.837762 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.057s	user 0.021s	sys 0.032s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25866,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:32.838584 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:32.855000 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.855633 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:33.030074 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.174s	user 0.126s	sys 0.045s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836135,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2039,"lbm_read_time_us":11129,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38023,"lbm_writes_lt_1ms":643,"mutex_wait_us":445,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3000}
I20260812 06:20:33.030737 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=14.095187
I20260812 06:20:33.075812 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19897,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.076431 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:33.087658 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.088155 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:33.252028 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.164s	user 0.118s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":961,"lbm_read_time_us":11171,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33000,"lbm_writes_lt_1ms":543,"mutex_wait_us":102,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:20:33.252944 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=11.118625
I20260812 06:20:33.305274 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.052s	user 0.031s	sys 0.012s Metrics: {"bytes_written":13456165,"delete_count":0,"lbm_write_time_us":19455,"lbm_writes_lt_1ms":331,"reinsert_count":0,"update_count":1640}
I20260812 06:20:33.305815 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:33.316689 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.011s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3364209,"delete_count":0,"lbm_write_time_us":3397,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:20:33.317237 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=2.188937
I20260812 06:20:33.327730 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3804,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:33.328259 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushMRSOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:33.363150 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushMRSOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.035s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1730,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1886,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:33.363920 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling LogGCOp(697dde97a74b4e92ae9c241f117407e1): free 136275468 bytes of WAL
I20260812 06:20:33.364346 17150 log_reader.cc:385] T 697dde97a74b4e92ae9c241f117407e1: removed 13 log segments from log reader
I20260812 06:20:33.364392 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000027 (ops 129-132)
I20260812 06:20:33.364423 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000028 (ops 133-137)
I20260812 06:20:33.364466 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000029 (ops 138-142)
I20260812 06:20:33.364507 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000030 (ops 143-147)
I20260812 06:20:33.364531 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000031 (ops 148-152)
I20260812 06:20:33.364571 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000032 (ops 153-157)
I20260812 06:20:33.364610 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000033 (ops 158-162)
I20260812 06:20:33.364634 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000034 (ops 163-167)
I20260812 06:20:33.364671 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000035 (ops 168-172)
I20260812 06:20:33.364708 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000036 (ops 173-177)
I20260812 06:20:33.364749 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000037 (ops 178-182)
I20260812 06:20:33.364789 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000038 (ops 183-187)
I20260812 06:20:33.364826 17150 log.cc:1079] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/697dde97a74b4e92ae9c241f117407e1/wal-000000039 (ops 188-192)
I20260812 06:20:33.397126 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: LogGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:33.397559 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1): 493 bytes on disk
I20260812 06:20:33.398039 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: UndoDeltaBlockGCOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:20:33.398633 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=6.157687
I20260812 06:20:33.428493 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.030s	user 0.011s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12903,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:33.429060 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1): perf score=1.000000
I20260812 06:20:33.547780 16980 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.009s	user 1.876s	sys 0.111s
I20260812 06:20:33.641690 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: MajorDeltaCompactionOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.212s	user 0.139s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938758,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1295,"lbm_read_time_us":16455,"lbm_reads_lt_1ms":762,"lbm_write_time_us":38094,"lbm_writes_lt_1ms":743,"mutex_wait_us":633,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14976,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:20:33.642113 16980 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.005s	sys 0.000s
I20260812 06:20:33.642922 16980 tablet_server.cc:179] TabletServer@127.16.149.1:0 shutting down...
I20260812 06:20:33.643077 17260 maintenance_manager.cc:419] P 5b2e31a210904f8e8d922652fb0cae3d: Scheduling FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1): perf score=10.126437
I20260812 06:20:33.682199 17150 maintenance_manager.cc:643] P 5b2e31a210904f8e8d922652fb0cae3d: FlushDeltaMemStoresOp(697dde97a74b4e92ae9c241f117407e1) complete. Timing: real 0.039s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16262,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:33.683498 16980 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:33.683956 16980 tablet_replica.cc:333] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d: stopping tablet replica
I20260812 06:20:33.684222 16980 raft_consensus.cc:2243] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:33.684490 16980 raft_consensus.cc:2272] T 697dde97a74b4e92ae9c241f117407e1 P 5b2e31a210904f8e8d922652fb0cae3d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:33.699945 16980 tablet_server.cc:196] TabletServer@127.16.149.1:0 shutdown complete.
I20260812 06:20:33.705156 16980 master.cc:562] Master@127.16.149.62:39223 shutting down...
I20260812 06:20:33.709566 16980 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:33.709771 16980 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:33.709872 16980 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5b4433bfe503405fa066c7bd38f2b03a: stopping tablet replica
I20260812 06:20:33.722405 16980 master.cc:584] Master@127.16.149.62:39223 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5583 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:33.817030 16980 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.149.62:34453
I20260812 06:20:33.817461 16980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:33.819636 16980 server_base.cc:1061] running on GCE node
W20260812 06:20:33.819620 17316 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:20:33.819620 17318 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:20:33.819860 17323 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:20:33.820087 16980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:33.820132 16980 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:20:33.820148 16980 hybrid_clock.cc:648] HybridClock initialized: now 1786515633820148 us; error 0 us; skew 500 ppm
I20260812 06:20:33.821211 16980 webserver.cc:533] Webserver started at http://127.16.149.62:43269/ using document root <none> and password file <none>
I20260812 06:20:33.821426 16980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:33.821508 16980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:33.821590 16980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:33.822079 16980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/master-0-root/instance:
uuid: "1cda9363bf1d47f9a7875860fe526c52"
format_stamp: "Formatted at 2026-08-12 06:20:33 on dist-test-slave-6ntk"
I20260812 06:20:33.823673 16980 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:33.824744 17334 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:20:33.825083 16980 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:33.825198 16980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/master-0-root
uuid: "1cda9363bf1d47f9a7875860fe526c52"
format_stamp: "Formatted at 2026-08-12 06:20:33 on dist-test-slave-6ntk"
I20260812 06:20:33.825320 16980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-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:20:33.844815 16980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:33.845347 16980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:33.850323 16980 rpc_server.cc:307] RPC server started. Bound to: 127.16.149.62:34453
I20260812 06:20:33.854606 17430 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.149.62:34453 every 8 connection(s)
I20260812 06:20:33.855121 17432 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:20:33.872129 17432 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52: Bootstrap starting.
I20260812 06:20:33.873126 17432 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:33.874517 17432 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52: No bootstrap required, opened a new log
I20260812 06:20:33.874980 17432 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1cda9363bf1d47f9a7875860fe526c52" member_type: VOTER }
I20260812 06:20:33.875077 17432 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:33.875099 17432 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1cda9363bf1d47f9a7875860fe526c52, State: Initialized, Role: FOLLOWER
I20260812 06:20:33.875262 17432 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [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: "1cda9363bf1d47f9a7875860fe526c52" member_type: VOTER }
I20260812 06:20:33.875337 17432 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:33.875406 17432 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:33.875492 17432 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:33.876297 17432 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1cda9363bf1d47f9a7875860fe526c52" member_type: VOTER }
I20260812 06:20:33.876426 17432 leader_election.cc:304] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [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: 1cda9363bf1d47f9a7875860fe526c52; no voters: 
I20260812 06:20:33.876647 17432 leader_election.cc:290] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:33.876837 17435 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:33.877086 17435 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 1 LEADER]: Becoming Leader. State: Replica: 1cda9363bf1d47f9a7875860fe526c52, State: Running, Role: LEADER
I20260812 06:20:33.877143 17432 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:33.877245 17435 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [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: "1cda9363bf1d47f9a7875860fe526c52" member_type: VOTER }
I20260812 06:20:33.877699 17436 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1cda9363bf1d47f9a7875860fe526c52" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1cda9363bf1d47f9a7875860fe526c52" member_type: VOTER } }
I20260812 06:20:33.877841 17436 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:33.877712 17437 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1cda9363bf1d47f9a7875860fe526c52. Latest consensus state: current_term: 1 leader_uuid: "1cda9363bf1d47f9a7875860fe526c52" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1cda9363bf1d47f9a7875860fe526c52" member_type: VOTER } }
I20260812 06:20:33.877936 17437 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:33.878557 17445 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:33.879470 17445 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:33.879714 16980 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:33.881621 17445 catalog_manager.cc:1383] Generated new cluster ID: ba68e49033c1436188bb76d13836c266
I20260812 06:20:33.881685 17445 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:33.895824 17445 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:33.896456 17445 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:33.902537 17445 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52: Generated new TSK 0
I20260812 06:20:33.902726 17445 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:33.912379 16980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:33.914942 17461 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:20:33.914921 17465 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:20:33.915155 16980 server_base.cc:1061] running on GCE node
W20260812 06:20:33.914960 17460 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:20:33.915514 16980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:33.915565 16980 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:20:33.915582 16980 hybrid_clock.cc:648] HybridClock initialized: now 1786515633915582 us; error 0 us; skew 500 ppm
I20260812 06:20:33.916603 16980 webserver.cc:533] Webserver started at http://127.16.149.1:43049/ using document root <none> and password file <none>
I20260812 06:20:33.916795 16980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:33.916908 16980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:33.917004 16980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:33.917438 16980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/instance:
uuid: "9276f39f899b42459461cc6f4b52ed82"
format_stamp: "Formatted at 2026-08-12 06:20:33 on dist-test-slave-6ntk"
I20260812 06:20:33.919140 16980 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:33.920231 17472 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:20:33.920591 16980 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:33.920689 16980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root
uuid: "9276f39f899b42459461cc6f4b52ed82"
format_stamp: "Formatted at 2026-08-12 06:20:33 on dist-test-slave-6ntk"
I20260812 06:20:33.920785 16980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-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:20:33.936146 16980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:33.936630 16980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:33.937023 16980 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:33.937531 16980 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:33.937594 16980 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:33.937664 16980 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:33.937714 16980 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:33.942224 16980 rpc_server.cc:307] RPC server started. Bound to: 127.16.149.1:42745
I20260812 06:20:33.942258 17590 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.149.1:42745 every 8 connection(s)
I20260812 06:20:33.951507 17591 heartbeater.cc:344] Connected to a master server at 127.16.149.62:34453
I20260812 06:20:33.951638 17591 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:33.951912 17591 heartbeater.cc:507] Master 127.16.149.62:34453 requested a full tablet report, sending...
I20260812 06:20:33.952698 17370 ts_manager.cc:194] Registered new tserver with Master: 9276f39f899b42459461cc6f4b52ed82 (127.16.149.1:42745)
I20260812 06:20:33.952744 16980 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010107563s
I20260812 06:20:33.953485 17370 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37496
I20260812 06:20:33.960758 17370 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37506:
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:20:33.970407 17527 tablet_service.cc:1511] Processing CreateTablet for tablet 7615eb3b7a5841d2959c3f6f70881c97 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2475364f6a7245d183b7a7a7554cbd62]), partition=
I20260812 06:20:33.970676 17527 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7615eb3b7a5841d2959c3f6f70881c97. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:33.972683 17608 tablet_bootstrap.cc:492] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Bootstrap starting.
I20260812 06:20:33.973604 17608 tablet_bootstrap.cc:654] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:33.974947 17608 tablet_bootstrap.cc:492] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: No bootstrap required, opened a new log
I20260812 06:20:33.975075 17608 ts_tablet_manager.cc:1403] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:33.975662 17608 raft_consensus.cc:359] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9276f39f899b42459461cc6f4b52ed82" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 42745 } }
I20260812 06:20:33.975782 17608 raft_consensus.cc:385] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:33.975838 17608 raft_consensus.cc:740] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9276f39f899b42459461cc6f4b52ed82, State: Initialized, Role: FOLLOWER
I20260812 06:20:33.975984 17608 consensus_queue.cc:260] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [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: "9276f39f899b42459461cc6f4b52ed82" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 42745 } }
I20260812 06:20:33.976089 17608 raft_consensus.cc:399] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:33.976151 17608 raft_consensus.cc:493] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:33.976217 17608 raft_consensus.cc:3060] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:33.977027 17608 raft_consensus.cc:515] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9276f39f899b42459461cc6f4b52ed82" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 42745 } }
I20260812 06:20:33.977192 17608 leader_election.cc:304] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [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: 9276f39f899b42459461cc6f4b52ed82; no voters: 
I20260812 06:20:33.977442 17608 leader_election.cc:290] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:33.977586 17612 raft_consensus.cc:2804] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:33.977818 17612 raft_consensus.cc:697] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 1 LEADER]: Becoming Leader. State: Replica: 9276f39f899b42459461cc6f4b52ed82, State: Running, Role: LEADER
I20260812 06:20:33.977928 17591 heartbeater.cc:499] Master 127.16.149.62:34453 was elected leader, sending a full tablet report...
I20260812 06:20:33.978020 17612 consensus_queue.cc:237] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [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: "9276f39f899b42459461cc6f4b52ed82" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 42745 } }
I20260812 06:20:33.977909 17608 ts_tablet_manager.cc:1434] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:33.979521 17370 catalog_manager.cc:5719] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9276f39f899b42459461cc6f4b52ed82 (127.16.149.1). New cstate: current_term: 1 leader_uuid: "9276f39f899b42459461cc6f4b52ed82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9276f39f899b42459461cc6f4b52ed82" member_type: VOTER last_known_addr { host: "127.16.149.1" port: 42745 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:34.041702 16980 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.018s	sys 0.004s
I20260812 06:20:34.193256 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=19.054940
I20260812 06:20:34.368569 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.175s	user 0.121s	sys 0.044s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":936,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45389,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:34.369338 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling LogGCOp(7615eb3b7a5841d2959c3f6f70881c97): free 20743880 bytes of WAL
I20260812 06:20:34.369609 17481 log_reader.cc:385] T 7615eb3b7a5841d2959c3f6f70881c97: removed 2 log segments from log reader
I20260812 06:20:34.369656 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000001 (ops 1-6)
I20260812 06:20:34.369714 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000002 (ops 7-11)
I20260812 06:20:34.374284 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: LogGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:34.374735 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97): 16411394 bytes on disk
I20260812 06:20:34.375240 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:20:34.375696 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:34.396490 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.021s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.397008 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:34.570921 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.174s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":107,"lbm_read_time_us":11480,"lbm_reads_lt_1ms":460,"lbm_write_time_us":32507,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":334,"threads_started":5,"update_count":2000}
I20260812 06:20:34.571621 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=11.118625
I20260812 06:20:34.604452 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.033s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14379,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:34.604969 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:34.624969 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5883,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:34.625578 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:34.760941 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.135s	user 0.109s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":9288,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26973,"lbm_writes_lt_1ms":443,"mutex_wait_us":80,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:20:34.761626 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=11.118625
I20260812 06:20:34.818686 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.057s	user 0.041s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":20738,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:34.819270 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:34.834038 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.834573 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:34.850231 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6002,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:34.851038 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:35.042052 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.191s	user 0.118s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":887,"lbm_read_time_us":13184,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31001,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:35.042744 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:35.104770 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.062s	user 0.020s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22750,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:35.105333 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:35.116706 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.117218 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:35.304695 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.187s	user 0.131s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":13744,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31961,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":214912,"update_count":2500}
I20260812 06:20:35.305480 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:35.371670 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.066s	user 0.037s	sys 0.027s Metrics: {"bytes_written":16409948,"delete_count":0,"lbm_write_time_us":22854,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:35.372282 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:35.384473 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4661,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.385236 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:35.581815 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.196s	user 0.124s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":676,"lbm_read_time_us":13810,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32491,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:20:35.582612 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:35.634584 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.052s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21898,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:20:35.635110 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:35.647393 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.647933 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:35.687235 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.039s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1606,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2189,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:35.688127 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling LogGCOp(7615eb3b7a5841d2959c3f6f70881c97): free 112239259 bytes of WAL
I20260812 06:20:35.688465 17481 log_reader.cc:385] T 7615eb3b7a5841d2959c3f6f70881c97: removed 11 log segments from log reader
I20260812 06:20:35.688544 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000003 (ops 12-16)
I20260812 06:20:35.688592 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000004 (ops 17-21)
I20260812 06:20:35.688648 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000005 (ops 22-26)
I20260812 06:20:35.688691 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000006 (ops 27-31)
I20260812 06:20:35.688731 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000007 (ops 32-36)
I20260812 06:20:35.688771 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000008 (ops 37-40)
I20260812 06:20:35.688819 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000009 (ops 41-45)
I20260812 06:20:35.688858 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000010 (ops 46-50)
I20260812 06:20:35.688895 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000011 (ops 51-55)
I20260812 06:20:35.688935 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000012 (ops 56-60)
I20260812 06:20:35.688975 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000013 (ops 61-65)
I20260812 06:20:35.715516 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: LogGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.027s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:20:35.716038 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97): 447 bytes on disk
I20260812 06:20:35.716729 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:20:35.717329 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:35.744155 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.027s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.744696 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:35.755947 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.756453 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:36.010732 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.254s	user 0.175s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":970,"lbm_read_time_us":16508,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42013,"lbm_writes_lt_1ms":743,"mutex_wait_us":87,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":116,"threads_started":1,"update_count":3500}
I20260812 06:20:36.011560 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=18.063937
I20260812 06:20:36.080427 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.068s	user 0.030s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27785,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:36.080987 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:36.093072 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:36.093778 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:36.308990 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.215s	user 0.109s	sys 0.100s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":845,"lbm_read_time_us":14161,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35566,"lbm_writes_lt_1ms":643,"mutex_wait_us":74,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:20:36.310832 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=17.071750
I20260812 06:20:36.367046 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.056s	user 0.041s	sys 0.013s Metrics: {"bytes_written":18707251,"delete_count":0,"lbm_write_time_us":24518,"lbm_writes_lt_1ms":459,"reinsert_count":0,"update_count":2280}
I20260812 06:20:36.367775 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.196750
I20260812 06:20:36.385169 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.017s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2215508,"delete_count":0,"lbm_write_time_us":2472,"lbm_writes_lt_1ms":57,"reinsert_count":0,"update_count":270}
I20260812 06:20:36.385762 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:36.395989 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:36.396564 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:36.616041 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.219s	user 0.134s	sys 0.085s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877164,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":895,"lbm_read_time_us":15120,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35492,"lbm_writes_lt_1ms":643,"mutex_wait_us":385,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:20:36.616686 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:36.669895 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.053s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23869,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:36.670482 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:36.688540 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6917,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:36.689148 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:36.864953 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.176s	user 0.128s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":618,"lbm_read_time_us":12455,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28605,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:36.865784 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:36.918718 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.053s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22521,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:36.919484 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:36.937888 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.018s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:36.938598 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:37.116464 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.178s	user 0.111s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":644,"lbm_read_time_us":14266,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29668,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:37.117192 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=11.118625
I20260812 06:20:37.149402 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.032s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13501,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:37.150400 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:37.174417 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.024s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5228,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:37.175027 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:37.216854 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.042s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1990,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:37.217520 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=3.181125
I20260812 06:20:37.239944 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.022s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":7037,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:20:37.240437 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling LogGCOp(7615eb3b7a5841d2959c3f6f70881c97): free 120100389 bytes of WAL
I20260812 06:20:37.240667 17481 log_reader.cc:385] T 7615eb3b7a5841d2959c3f6f70881c97: removed 12 log segments from log reader
I20260812 06:20:37.240713 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000014 (ops 66-70)
I20260812 06:20:37.240743 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000015 (ops 71-75)
I20260812 06:20:37.240813 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000016 (ops 76-80)
I20260812 06:20:37.240855 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000017 (ops 81-84)
I20260812 06:20:37.240896 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000018 (ops 85-89)
I20260812 06:20:37.240936 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000019 (ops 90-94)
I20260812 06:20:37.240975 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000020 (ops 95-98)
I20260812 06:20:37.241014 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000021 (ops 99-103)
I20260812 06:20:37.241057 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000022 (ops 104-108)
I20260812 06:20:37.241098 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000023 (ops 109-113)
I20260812 06:20:37.241124 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000024 (ops 114-118)
I20260812 06:20:37.241163 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000025 (ops 119-122)
I20260812 06:20:37.267812 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: LogGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:37.268406 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97): 462 bytes on disk
I20260812 06:20:37.269004 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:20:37.269613 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:37.285540 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.016s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4184711,"delete_count":0,"lbm_write_time_us":4575,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:20:37.286186 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:37.300563 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5285,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:37.301304 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:37.541339 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.240s	user 0.158s	sys 0.073s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":250,"lbm_read_time_us":16475,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39160,"lbm_writes_lt_1ms":743,"mutex_wait_us":82,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:20:37.542171 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=18.063937
I20260812 06:20:37.596583 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.054s	user 0.043s	sys 0.008s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":23781,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:20:37.597332 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:37.610064 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:37.610565 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:37.783738 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.173s	user 0.148s	sys 0.024s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1190,"lbm_read_time_us":12987,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35777,"lbm_writes_lt_1ms":643,"mutex_wait_us":358,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":52096,"update_count":3000}
I20260812 06:20:37.784490 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:37.843300 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.059s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23943,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:37.843896 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:37.855907 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:37.856469 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:38.031867 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.175s	user 0.142s	sys 0.026s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":11695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30835,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:20:38.032760 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:38.083379 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.050s	user 0.042s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22427,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:38.084270 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:38.241087 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.157s	user 0.102s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":216,"lbm_read_time_us":9275,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27544,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:38.241717 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=11.118625
I20260812 06:20:38.290611 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.049s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":21771,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:38.291347 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:38.310930 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:38.311596 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:38.321991 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3733,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:38.322551 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:38.508409 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.186s	user 0.138s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1353,"lbm_read_time_us":13302,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29206,"lbm_writes_lt_1ms":543,"mutex_wait_us":421,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:38.509112 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:38.565734 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.056s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23940,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:38.566416 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:38.579131 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:38.579649 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:38.760033 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.180s	user 0.132s	sys 0.034s 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":822,"lbm_read_time_us":10909,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33119,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:38.760746 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=14.095187
I20260812 06:20:38.828693 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.068s	user 0.046s	sys 0.008s Metrics: {"bytes_written":16409914,"delete_count":0,"lbm_write_time_us":25235,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:38.829224 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:38.847724 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:38.848556 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:38.887642 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushMRSOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.039s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1637,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2376,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:38.888495 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling LogGCOp(7615eb3b7a5841d2959c3f6f70881c97): free 129320703 bytes of WAL
I20260812 06:20:38.888769 17481 log_reader.cc:385] T 7615eb3b7a5841d2959c3f6f70881c97: removed 13 log segments from log reader
I20260812 06:20:38.888820 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000026 (ops 123-127)
I20260812 06:20:38.888864 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000027 (ops 128-132)
I20260812 06:20:38.888890 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000028 (ops 133-137)
I20260812 06:20:38.888911 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000029 (ops 138-142)
I20260812 06:20:38.888933 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000030 (ops 143-147)
I20260812 06:20:38.888955 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000031 (ops 148-152)
I20260812 06:20:38.888985 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000032 (ops 153-157)
I20260812 06:20:38.889011 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000033 (ops 158-162)
I20260812 06:20:38.889045 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000034 (ops 163-166)
I20260812 06:20:38.889067 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000035 (ops 167-171)
I20260812 06:20:38.889089 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000036 (ops 172-176)
I20260812 06:20:38.889118 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000037 (ops 177-180)
I20260812 06:20:38.889140 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000038 (ops 181-185)
I20260812 06:20:38.922201 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: LogGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.033s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:20:38.922772 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97): 495 bytes on disk
I20260812 06:20:38.923247 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: UndoDeltaBlockGCOp(7615eb3b7a5841d2959c3f6f70881c97) 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:20:38.923993 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=3.181125
I20260812 06:20:38.955629 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.031s	user 0.004s	sys 0.024s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7936,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:38.956229 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling LogGCOp(7615eb3b7a5841d2959c3f6f70881c97): free 12018004 bytes of WAL
I20260812 06:20:38.956486 17481 log_reader.cc:385] T 7615eb3b7a5841d2959c3f6f70881c97: removed 1 log segments from log reader
I20260812 06:20:38.956537 17481 log.cc:1079] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: Deleting log segment in path: /tmp/dist-test-taskJ7_9nc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515628222398-16980-0/minicluster-data/ts-0-root/wals/7615eb3b7a5841d2959c3f6f70881c97/wal-000000039 (ops 186-190)
I20260812 06:20:38.959121 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: LogGCOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:38.959625 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=2.188937
I20260812 06:20:38.970647 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:38.971349 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=1.000000
I20260812 06:20:39.238883 16980 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.197s	user 1.964s	sys 0.174s
I20260812 06:20:39.253747 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: MajorDeltaCompactionOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.282s	user 0.192s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1079,"lbm_read_time_us":18573,"lbm_reads_lt_1ms":774,"lbm_write_time_us":47389,"lbm_writes_lt_1ms":743,"mutex_wait_us":67,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":117,"threads_started":1,"update_count":3500}
I20260812 06:20:39.254527 17592 maintenance_manager.cc:419] P 9276f39f899b42459461cc6f4b52ed82: Scheduling FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97): perf score=18.063937
I20260812 06:20:39.294412 16980 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.003s	sys 0.000s
I20260812 06:20:39.294996 16980 tablet_server.cc:179] TabletServer@127.16.149.1:0 shutting down...
I20260812 06:20:39.313699 17481 maintenance_manager.cc:643] P 9276f39f899b42459461cc6f4b52ed82: FlushDeltaMemStoresOp(7615eb3b7a5841d2959c3f6f70881c97) complete. Timing: real 0.059s	user 0.031s	sys 0.024s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":26646,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:39.314420 16980 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:39.314724 16980 tablet_replica.cc:333] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82: stopping tablet replica
I20260812 06:20:39.314894 16980 raft_consensus.cc:2243] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:39.315080 16980 raft_consensus.cc:2272] T 7615eb3b7a5841d2959c3f6f70881c97 P 9276f39f899b42459461cc6f4b52ed82 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:39.329109 16980 tablet_server.cc:196] TabletServer@127.16.149.1:0 shutdown complete.
I20260812 06:20:39.332571 16980 master.cc:562] Master@127.16.149.62:34453 shutting down...
I20260812 06:20:39.335953 16980 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:39.336125 16980 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:39.336175 16980 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1cda9363bf1d47f9a7875860fe526c52: stopping tablet replica
I20260812 06:20:39.348708 16980 master.cc:584] Master@127.16.149.62:34453 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5628 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11212 ms total)

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