[==========] 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:19:23.405311  8866 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.168.190:37185
I20260812 06:19:23.406327  8866 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:19:23.406919  8866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:23.413067  8879 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:19:23.413158  8866 server_base.cc:1061] running on GCE node
W20260812 06:19:23.413250  8880 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:19:23.413149  8882 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:19:23.413743  8866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:23.413858  8866 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:19:23.413902  8866 hybrid_clock.cc:648] HybridClock initialized: now 1786515563413900 us; error 0 us; skew 500 ppm
I20260812 06:19:23.415567  8866 webserver.cc:533] Webserver started at http://127.8.168.190:43507/ using document root <none> and password file <none>
I20260812 06:19:23.416077  8866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:23.416132  8866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:23.416359  8866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:23.417896  8866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/master-0-root/instance:
uuid: "b0a4b3f9e0824587ae9b790ae6814c5b"
format_stamp: "Formatted at 2026-08-12 06:19:23 on dist-test-slave-4tdj"
I20260812 06:19:23.421239  8866 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.002s
I20260812 06:19:23.423460  8891 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:19:23.424397  8866 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:23.424499  8866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/master-0-root
uuid: "b0a4b3f9e0824587ae9b790ae6814c5b"
format_stamp: "Formatted at 2026-08-12 06:19:23 on dist-test-slave-4tdj"
I20260812 06:19:23.424584  8866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-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:19:23.446202  8866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:23.446882  8866 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:19:23.447037  8866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:23.454315  8866 rpc_server.cc:307] RPC server started. Bound to: 127.8.168.190:37185
I20260812 06:19:23.454331  8981 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.168.190:37185 every 8 connection(s)
I20260812 06:19:23.456519  8982 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:19:23.461987  8982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b: Bootstrap starting.
I20260812 06:19:23.464329  8982 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:23.465251  8982 log.cc:826] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:23.467037  8982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b: No bootstrap required, opened a new log
I20260812 06:19:23.469841  8982 raft_consensus.cc:359] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0a4b3f9e0824587ae9b790ae6814c5b" member_type: VOTER }
I20260812 06:19:23.470007  8982 raft_consensus.cc:385] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:23.470077  8982 raft_consensus.cc:740] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b0a4b3f9e0824587ae9b790ae6814c5b, State: Initialized, Role: FOLLOWER
I20260812 06:19:23.470696  8982 consensus_queue.cc:260] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [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: "b0a4b3f9e0824587ae9b790ae6814c5b" member_type: VOTER }
I20260812 06:19:23.470856  8982 raft_consensus.cc:399] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:23.470924  8982 raft_consensus.cc:493] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:23.471048  8982 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:23.471829  8982 raft_consensus.cc:515] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0a4b3f9e0824587ae9b790ae6814c5b" member_type: VOTER }
I20260812 06:19:23.472267  8982 leader_election.cc:304] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [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: b0a4b3f9e0824587ae9b790ae6814c5b; no voters: 
I20260812 06:19:23.472571  8982 leader_election.cc:290] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:23.472674  8985 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:23.472899  8985 raft_consensus.cc:697] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 1 LEADER]: Becoming Leader. State: Replica: b0a4b3f9e0824587ae9b790ae6814c5b, State: Running, Role: LEADER
I20260812 06:19:23.473332  8985 consensus_queue.cc:237] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [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: "b0a4b3f9e0824587ae9b790ae6814c5b" member_type: VOTER }
I20260812 06:19:23.473608  8982 sys_catalog.cc:565] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:23.475219  8986 sys_catalog.cc:455] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b0a4b3f9e0824587ae9b790ae6814c5b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0a4b3f9e0824587ae9b790ae6814c5b" member_type: VOTER } }
I20260812 06:19:23.475250  8987 sys_catalog.cc:455] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [sys.catalog]: SysCatalogTable state changed. Reason: New leader b0a4b3f9e0824587ae9b790ae6814c5b. Latest consensus state: current_term: 1 leader_uuid: "b0a4b3f9e0824587ae9b790ae6814c5b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0a4b3f9e0824587ae9b790ae6814c5b" member_type: VOTER } }
I20260812 06:19:23.475361  8987 sys_catalog.cc:458] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:23.475359  8986 sys_catalog.cc:458] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:23.475802  9013 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:23.475903  8866 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:23.478031  9013 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:23.482388  9013 catalog_manager.cc:1383] Generated new cluster ID: 0d21c1297f8a4c49bfa5833174c45abe
I20260812 06:19:23.482457  9013 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:23.488848  9013 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:23.489936  9013 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:23.502419  9013 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b: Generated new TSK 0
I20260812 06:19:23.503185  9013 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:23.508297  8866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:23.510798  9027 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:19:23.510887  9025 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:19:23.510991  9024 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:19:23.511181  8866 server_base.cc:1061] running on GCE node
I20260812 06:19:23.511339  8866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:23.511375  8866 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:19:23.511395  8866 hybrid_clock.cc:648] HybridClock initialized: now 1786515563511395 us; error 0 us; skew 500 ppm
I20260812 06:19:23.512231  8866 webserver.cc:533] Webserver started at http://127.8.168.129:38317/ using document root <none> and password file <none>
I20260812 06:19:23.512387  8866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:23.512439  8866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:23.512511  8866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:23.512871  8866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/instance:
uuid: "24b28c2a8cb64334ac51b74bd094d083"
format_stamp: "Formatted at 2026-08-12 06:19:23 on dist-test-slave-4tdj"
I20260812 06:19:23.514245  8866 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:23.515203  9040 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:19:23.515452  8866 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:23.515519  8866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root
uuid: "24b28c2a8cb64334ac51b74bd094d083"
format_stamp: "Formatted at 2026-08-12 06:19:23 on dist-test-slave-4tdj"
I20260812 06:19:23.515589  8866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-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:19:23.528003  8866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:23.528434  8866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:23.528944  8866 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:23.529801  8866 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:23.529855  8866 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:23.529901  8866 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:23.529932  8866 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:23.535838  8866 rpc_server.cc:307] RPC server started. Bound to: 127.8.168.129:33553
I20260812 06:19:23.535871  9155 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.168.129:33553 every 8 connection(s)
I20260812 06:19:23.545076  9156 heartbeater.cc:344] Connected to a master server at 127.8.168.190:37185
I20260812 06:19:23.545344  9156 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:23.545775  9156 heartbeater.cc:507] Master 127.8.168.190:37185 requested a full tablet report, sending...
I20260812 06:19:23.547119  8920 ts_manager.cc:194] Registered new tserver with Master: 24b28c2a8cb64334ac51b74bd094d083 (127.8.168.129:33553)
I20260812 06:19:23.547577  8866 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011156686s
I20260812 06:19:23.548271  8920 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46088
I20260812 06:19:23.557418  8920 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46090:
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:19:23.571461  9090 tablet_service.cc:1511] Processing CreateTablet for tablet 46abffaf7bc24860a6ec91e35c0189d6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=763576de8a824a0e890cd5d37e925138]), partition=
I20260812 06:19:23.571887  9090 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 46abffaf7bc24860a6ec91e35c0189d6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:23.574051  9179 tablet_bootstrap.cc:492] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Bootstrap starting.
I20260812 06:19:23.575073  9179 tablet_bootstrap.cc:654] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:23.576117  9179 tablet_bootstrap.cc:492] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: No bootstrap required, opened a new log
I20260812 06:19:23.576213  9179 ts_tablet_manager.cc:1403] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:23.576625  9179 raft_consensus.cc:359] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "24b28c2a8cb64334ac51b74bd094d083" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 33553 } }
I20260812 06:19:23.576735  9179 raft_consensus.cc:385] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:23.576767  9179 raft_consensus.cc:740] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 24b28c2a8cb64334ac51b74bd094d083, State: Initialized, Role: FOLLOWER
I20260812 06:19:23.576911  9179 consensus_queue.cc:260] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [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: "24b28c2a8cb64334ac51b74bd094d083" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 33553 } }
I20260812 06:19:23.577001  9179 raft_consensus.cc:399] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:23.577046  9179 raft_consensus.cc:493] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:23.577095  9179 raft_consensus.cc:3060] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:23.577805  9179 raft_consensus.cc:515] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "24b28c2a8cb64334ac51b74bd094d083" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 33553 } }
I20260812 06:19:23.577935  9179 leader_election.cc:304] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [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: 24b28c2a8cb64334ac51b74bd094d083; no voters: 
I20260812 06:19:23.578126  9179 leader_election.cc:290] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:23.578240  9181 raft_consensus.cc:2804] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:23.578430  9181 raft_consensus.cc:697] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 1 LEADER]: Becoming Leader. State: Replica: 24b28c2a8cb64334ac51b74bd094d083, State: Running, Role: LEADER
I20260812 06:19:23.578526  9179 ts_tablet_manager.cc:1434] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:23.578627  9181 consensus_queue.cc:237] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [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: "24b28c2a8cb64334ac51b74bd094d083" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 33553 } }
I20260812 06:19:23.578831  9156 heartbeater.cc:499] Master 127.8.168.190:37185 was elected leader, sending a full tablet report...
I20260812 06:19:23.581597  8920 catalog_manager.cc:5719] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 reported cstate change: term changed from 0 to 1, leader changed from <none> to 24b28c2a8cb64334ac51b74bd094d083 (127.8.168.129). New cstate: current_term: 1 leader_uuid: "24b28c2a8cb64334ac51b74bd094d083" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "24b28c2a8cb64334ac51b74bd094d083" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 33553 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:23.655089  8866 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.024s	sys 0.008s
I20260812 06:19:23.786844  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=19.054940
I20260812 06:19:23.933449  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.146s	user 0.115s	sys 0.028s Metrics: {"bytes_written":9025564,"cfile_init":1,"compiler_manager_pool.queue_time_us":188,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":920,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33835,"lbm_writes_lt_1ms":677,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":266624,"thread_start_us":117,"threads_started":1,"update_count":1100}
I20260812 06:19:23.934592  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling LogGCOp(46abffaf7bc24860a6ec91e35c0189d6): free 20743880 bytes of WAL
I20260812 06:19:23.934883  9052 log_reader.cc:385] T 46abffaf7bc24860a6ec91e35c0189d6: removed 2 log segments from log reader
I20260812 06:19:23.934944  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000001 (ops 1-6)
I20260812 06:19:23.935000  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000002 (ops 7-11)
I20260812 06:19:23.938701  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: LogGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:23.939023  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6): 16411395 bytes on disk
I20260812 06:19:23.939565  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.939949  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:23.953830  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":4974,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:23.954496  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:24.080871  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.126s	user 0.082s	sys 0.033s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569847,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":665,"lbm_read_time_us":8508,"lbm_reads_lt_1ms":364,"lbm_write_time_us":22342,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":270,"threads_started":5,"update_count":1500}
I20260812 06:19:24.081346  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:24.130493  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.049s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17578,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:24.130925  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:24.140604  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.140972  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:24.264072  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.123s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":10218,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22456,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.264648  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=7.149875
I20260812 06:19:24.289567  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.025s	user 0.019s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10361,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:24.290043  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:24.299772  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3404,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.300279  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:24.417209  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.117s	user 0.078s	sys 0.032s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":8423,"lbm_reads_lt_1ms":372,"lbm_write_time_us":17445,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:24.419651  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=7.149875
I20260812 06:19:24.446431  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.026s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11393,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:24.446842  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:24.457439  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.457881  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:24.563570  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.106s	user 0.081s	sys 0.023s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":556,"lbm_read_time_us":7370,"lbm_reads_lt_1ms":364,"lbm_write_time_us":18531,"lbm_writes_lt_1ms":343,"mutex_wait_us":251,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:19:24.564249  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=7.149875
I20260812 06:19:24.590843  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.026s	user 0.022s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11635,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:24.591308  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:24.605403  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5413,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.605935  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:24.723067  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.117s	user 0.077s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":580,"lbm_read_time_us":7982,"lbm_reads_lt_1ms":372,"lbm_write_time_us":17520,"lbm_writes_lt_1ms":343,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:24.723544  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:24.765614  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.042s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15166,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:24.766103  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:24.776203  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3812,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.776805  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:24.898425  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.121s	user 0.113s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":617,"lbm_read_time_us":8470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23451,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:24.898932  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:24.937587  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.039s	user 0.010s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12450,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:24.938112  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:24.953161  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.953564  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:25.079685  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.126s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1029,"lbm_read_time_us":8071,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24753,"lbm_writes_lt_1ms":443,"mutex_wait_us":462,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:19:25.080201  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:25.122820  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.042s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13109,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.123338  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:25.133525  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3856,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.133952  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:25.162520  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.028s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1277,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1479,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:25.163318  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:25.301721  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.138s	user 0.098s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":8344,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21956,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:25.302331  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling LogGCOp(46abffaf7bc24860a6ec91e35c0189d6): free 112239313 bytes of WAL
I20260812 06:19:25.302687  9052 log_reader.cc:385] T 46abffaf7bc24860a6ec91e35c0189d6: removed 11 log segments from log reader
I20260812 06:19:25.302736  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000003 (ops 12-16)
I20260812 06:19:25.302774  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000004 (ops 17-20)
I20260812 06:19:25.302803  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000005 (ops 21-25)
I20260812 06:19:25.302829  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000006 (ops 26-30)
I20260812 06:19:25.302857  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000007 (ops 31-35)
I20260812 06:19:25.302886  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000008 (ops 36-40)
I20260812 06:19:25.302917  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000009 (ops 41-45)
I20260812 06:19:25.302946  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000010 (ops 46-50)
I20260812 06:19:25.302975  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000011 (ops 51-55)
I20260812 06:19:25.303005  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000012 (ops 56-60)
I20260812 06:19:25.303043  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000013 (ops 61-65)
I20260812 06:19:25.325402  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: LogGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.023s	user 0.004s	sys 0.016s Metrics: {}
I20260812 06:19:25.325798  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6): 447 bytes on disk
I20260812 06:19:25.326272  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:25.326853  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=14.095187
I20260812 06:19:25.367748  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.041s	user 0.015s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18710,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.368397  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:25.384543  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.384980  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:25.551538  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.166s	user 0.082s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":790,"lbm_read_time_us":9675,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27229,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:25.552053  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=14.095187
I20260812 06:19:25.592324  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.040s	user 0.030s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17452,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.592803  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:25.608206  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.608656  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:25.754365  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.146s	user 0.127s	sys 0.017s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1540,"lbm_read_time_us":9213,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29760,"lbm_writes_lt_1ms":543,"mutex_wait_us":917,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:25.754886  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:25.786684  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.030s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12471588,"delete_count":0,"lbm_write_time_us":13866,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":306,"reinsert_count":0,"update_count":1520}
I20260812 06:19:25.787328  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:25.803803  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:19:25.804469  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:25.924394  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.120s	user 0.091s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":7147,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21159,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:25.924962  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=11.118625
I20260812 06:19:25.954217  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.029s	user 0.013s	sys 0.012s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":11771,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:25.954702  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:25.965937  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.966574  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:26.086906  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.120s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":7318,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23361,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:19:26.087460  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:26.134065  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.046s	user 0.018s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16230,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.134707  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:26.149603  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.150089  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:26.283401  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.133s	user 0.088s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":901,"lbm_read_time_us":9935,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22142,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:26.283970  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:26.324033  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.040s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13160,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.324515  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:26.339723  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.340314  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:26.462688  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.122s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":10014,"lbm_read_time_us":7656,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22812,"lbm_writes_lt_1ms":443,"mutex_wait_us":3180,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:26.463359  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:26.500384  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.037s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14180,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.500841  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:26.510998  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.511674  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:26.541620  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":1464,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1826,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:26.542339  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling LogGCOp(46abffaf7bc24860a6ec91e35c0189d6): free 121006445 bytes of WAL
I20260812 06:19:26.542547  9052 log_reader.cc:385] T 46abffaf7bc24860a6ec91e35c0189d6: removed 12 log segments from log reader
I20260812 06:19:26.542593  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000014 (ops 66-70)
I20260812 06:19:26.542622  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000015 (ops 71-75)
I20260812 06:19:26.542654  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000016 (ops 76-80)
I20260812 06:19:26.542687  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000017 (ops 81-85)
I20260812 06:19:26.542718  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000018 (ops 86-90)
I20260812 06:19:26.542750  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000019 (ops 91-95)
I20260812 06:19:26.542783  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000020 (ops 96-100)
I20260812 06:19:26.542814  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000021 (ops 101-104)
I20260812 06:19:26.542845  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000022 (ops 105-109)
I20260812 06:19:26.542876  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000023 (ops 110-114)
I20260812 06:19:26.542906  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000024 (ops 115-119)
I20260812 06:19:26.542937  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000025 (ops 120-124)
I20260812 06:19:26.564459  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: LogGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:26.564985  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6): 472 bytes on disk
I20260812 06:19:26.565426  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:26.566136  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=3.181125
I20260812 06:19:26.578274  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:26.578706  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling LogGCOp(46abffaf7bc24860a6ec91e35c0189d6): free 11564877 bytes of WAL
I20260812 06:19:26.578898  9052 log_reader.cc:385] T 46abffaf7bc24860a6ec91e35c0189d6: removed 1 log segments from log reader
I20260812 06:19:26.578950  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000026 (ops 125-128)
I20260812 06:19:26.580892  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: LogGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:26.581169  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:26.591233  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3303,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:26.591822  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:26.756687  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.164s	user 0.129s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2459,"lbm_read_time_us":10981,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31181,"lbm_writes_lt_1ms":643,"mutex_wait_us":1957,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":132480,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:19:26.757205  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=14.095187
I20260812 06:19:26.801656  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19697,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.802206  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:26.813853  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.814498  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:26.967711  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.153s	user 0.086s	sys 0.057s 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":1067,"lbm_read_time_us":9934,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27217,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:26.968313  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=14.095187
I20260812 06:19:27.007299  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.039s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17621,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:27.007965  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:27.140470  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.132s	user 0.083s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1121,"lbm_read_time_us":10293,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22303,"lbm_writes_lt_1ms":443,"mutex_wait_us":474,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.141042  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=11.118625
I20260812 06:19:27.174645  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.033s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":13809,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:27.175834  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:27.198575  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5037,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:27.199049  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:27.208527  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.009s	user 0.006s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.208932  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:27.362728  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.154s	user 0.103s	sys 0.047s 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":771,"lbm_read_time_us":9332,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25964,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:27.363243  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=11.118625
I20260812 06:19:27.396939  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14062,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:27.397507  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:27.410534  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4637,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:27.411031  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:27.519014  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.108s	user 0.083s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":746,"lbm_read_time_us":7086,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20608,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:27.519596  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:27.561031  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.041s	user 0.018s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16777,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.561740  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:27.578181  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.578769  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:27.704488  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.126s	user 0.089s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":7414,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24019,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.706640  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:27.742563  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.036s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13939,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.743074  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:27.753321  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.753895  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:27.780814  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushMRSOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.027s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1445,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1448,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:27.781617  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling LogGCOp(46abffaf7bc24860a6ec91e35c0189d6): free 108535682 bytes of WAL
I20260812 06:19:27.781865  9052 log_reader.cc:385] T 46abffaf7bc24860a6ec91e35c0189d6: removed 11 log segments from log reader
I20260812 06:19:27.781915  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000027 (ops 129-133)
I20260812 06:19:27.781955  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000028 (ops 134-138)
I20260812 06:19:27.781988  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000029 (ops 139-143)
I20260812 06:19:27.782015  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000030 (ops 144-148)
I20260812 06:19:27.782043  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000031 (ops 149-152)
I20260812 06:19:27.782068  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000032 (ops 153-157)
I20260812 06:19:27.782099  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000033 (ops 158-162)
I20260812 06:19:27.782130  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000034 (ops 163-167)
I20260812 06:19:27.782156  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000035 (ops 168-172)
I20260812 06:19:27.782195  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000036 (ops 173-176)
I20260812 06:19:27.782225  9052 log.cc:1079] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/46abffaf7bc24860a6ec91e35c0189d6/wal-000000037 (ops 177-181)
I20260812 06:19:27.806547  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: LogGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.025s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:27.806960  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=3.181125
I20260812 06:19:27.820848  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.014s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:27.821278  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:27.830694  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3431,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:27.831128  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:27.999663  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.168s	user 0.129s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":158,"lbm_read_time_us":10787,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31396,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":68,"threads_started":1,"update_count":3000}
I20260812 06:19:28.000224  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6): 447 bytes on disk
I20260812 06:19:28.001168  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: UndoDeltaBlockGCOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:28.001820  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=14.095187
I20260812 06:19:28.042488  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.043120  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=2.188937
I20260812 06:19:28.054741  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.055452  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:28.175873  8866 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.521s	user 1.650s	sys 0.149s
I20260812 06:19:28.201207  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.146s	user 0.115s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11290,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26773,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:28.201809  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=10.126437
I20260812 06:19:28.225771  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: FlushDeltaMemStoresOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11158,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.226235  9158 maintenance_manager.cc:419] P 24b28c2a8cb64334ac51b74bd094d083: Scheduling MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6): perf score=1.000000
I20260812 06:19:28.257270  8866 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.001s	sys 0.000s
I20260812 06:19:28.257906  8866 tablet_server.cc:179] TabletServer@127.8.168.129:0 shutting down...
I20260812 06:19:28.328105  9052 maintenance_manager.cc:643] P 24b28c2a8cb64334ac51b74bd094d083: MajorDeltaCompactionOp(46abffaf7bc24860a6ec91e35c0189d6) complete. Timing: real 0.102s	user 0.069s	sys 0.033s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":306,"lbm_read_time_us":7659,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20779,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":1500}
I20260812 06:19:28.328846  8866 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:28.329300  8866 tablet_replica.cc:333] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083: stopping tablet replica
I20260812 06:19:28.329520  8866 raft_consensus.cc:2243] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:28.329742  8866 raft_consensus.cc:2272] T 46abffaf7bc24860a6ec91e35c0189d6 P 24b28c2a8cb64334ac51b74bd094d083 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:28.344354  8866 tablet_server.cc:196] TabletServer@127.8.168.129:0 shutdown complete.
I20260812 06:19:28.359839  8866 master.cc:562] Master@127.8.168.190:37185 shutting down...
I20260812 06:19:28.363366  8866 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:28.363528  8866 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:28.363597  8866 tablet_replica.cc:333] T 00000000000000000000000000000000 P b0a4b3f9e0824587ae9b790ae6814c5b: stopping tablet replica
I20260812 06:19:28.375591  8866 master.cc:584] Master@127.8.168.190:37185 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5325 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:28.726996  8866 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.168.190:36627
I20260812 06:19:28.727388  8866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:28.729869  9215 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:19:28.729893  9219 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:19:28.729960  9213 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:19:28.729969  8866 server_base.cc:1061] running on GCE node
I20260812 06:19:28.730278  8866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:28.730343  8866 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:19:28.730361  8866 hybrid_clock.cc:648] HybridClock initialized: now 1786515568730361 us; error 0 us; skew 500 ppm
I20260812 06:19:28.731161  8866 webserver.cc:533] Webserver started at http://127.8.168.190:42287/ using document root <none> and password file <none>
I20260812 06:19:28.731333  8866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:28.731382  8866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:28.731458  8866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:28.731832  8866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/master-0-root/instance:
uuid: "8de71669f0744c5b919331e41401264c"
format_stamp: "Formatted at 2026-08-12 06:19:28 on dist-test-slave-4tdj"
I20260812 06:19:28.733253  8866 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:28.734164  9228 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:19:28.734426  8866 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:28.734499  8866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/master-0-root
uuid: "8de71669f0744c5b919331e41401264c"
format_stamp: "Formatted at 2026-08-12 06:19:28 on dist-test-slave-4tdj"
I20260812 06:19:28.734570  8866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-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:19:28.764688  8866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:28.765118  8866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:28.769155  8866 rpc_server.cc:307] RPC server started. Bound to: 127.8.168.190:36627
I20260812 06:19:28.780019  9313 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.168.190:36627 every 8 connection(s)
I20260812 06:19:28.781843  9314 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:19:28.783748  9314 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c: Bootstrap starting.
I20260812 06:19:28.784521  9314 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:28.785562  9314 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c: No bootstrap required, opened a new log
I20260812 06:19:28.786019  9314 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8de71669f0744c5b919331e41401264c" member_type: VOTER }
I20260812 06:19:28.786108  9314 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:28.786139  9314 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8de71669f0744c5b919331e41401264c, State: Initialized, Role: FOLLOWER
I20260812 06:19:28.786316  9314 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [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: "8de71669f0744c5b919331e41401264c" member_type: VOTER }
I20260812 06:19:28.786404  9314 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:28.786446  9314 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:28.786495  9314 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:28.787164  9314 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8de71669f0744c5b919331e41401264c" member_type: VOTER }
I20260812 06:19:28.787302  9314 leader_election.cc:304] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [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: 8de71669f0744c5b919331e41401264c; no voters: 
I20260812 06:19:28.787482  9314 leader_election.cc:290] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:28.787586  9319 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:28.787781  9319 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 1 LEADER]: Becoming Leader. State: Replica: 8de71669f0744c5b919331e41401264c, State: Running, Role: LEADER
I20260812 06:19:28.787897  9314 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:28.787911  9319 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [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: "8de71669f0744c5b919331e41401264c" member_type: VOTER }
I20260812 06:19:28.788378  9322 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8de71669f0744c5b919331e41401264c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8de71669f0744c5b919331e41401264c" member_type: VOTER } }
I20260812 06:19:28.788421  9329 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8de71669f0744c5b919331e41401264c. Latest consensus state: current_term: 1 leader_uuid: "8de71669f0744c5b919331e41401264c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8de71669f0744c5b919331e41401264c" member_type: VOTER } }
I20260812 06:19:28.788473  9322 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:28.788519  9329 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:28.789078  9335 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:28.789790  9335 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:28.789965  8866 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:28.791541  9335 catalog_manager.cc:1383] Generated new cluster ID: 50770b5817504b639b3c52f7c121cbff
I20260812 06:19:28.791587  9335 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:28.806625  9335 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:28.807168  9335 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:28.817198  9335 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c: Generated new TSK 0
I20260812 06:19:28.817350  9335 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:28.822110  8866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:28.823962  9359 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:19:28.823983  9357 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:19:28.824146  9362 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:19:28.824157  8866 server_base.cc:1061] running on GCE node
I20260812 06:19:28.824434  8866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:28.824476  8866 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:19:28.824491  8866 hybrid_clock.cc:648] HybridClock initialized: now 1786515568824490 us; error 0 us; skew 500 ppm
I20260812 06:19:28.825281  8866 webserver.cc:533] Webserver started at http://127.8.168.129:43981/ using document root <none> and password file <none>
I20260812 06:19:28.825415  8866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:28.825452  8866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:28.825508  8866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:28.825835  8866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/instance:
uuid: "63c794cf0a8a420fa5987ead88a1a2ed"
format_stamp: "Formatted at 2026-08-12 06:19:28 on dist-test-slave-4tdj"
I20260812 06:19:28.827214  8866 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:28.828050  9376 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:19:28.828262  8866 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:28.828328  8866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root
uuid: "63c794cf0a8a420fa5987ead88a1a2ed"
format_stamp: "Formatted at 2026-08-12 06:19:28 on dist-test-slave-4tdj"
I20260812 06:19:28.828393  8866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-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:19:28.836498  8866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:28.836792  8866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:28.837041  8866 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:28.837447  8866 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:28.837483  8866 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:28.837522  8866 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:28.837550  8866 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:28.841328  8866 rpc_server.cc:307] RPC server started. Bound to: 127.8.168.129:45297
I20260812 06:19:28.841355  9496 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.168.129:45297 every 8 connection(s)
I20260812 06:19:28.848901  9497 heartbeater.cc:344] Connected to a master server at 127.8.168.190:36627
I20260812 06:19:28.849012  9497 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:28.849233  9497 heartbeater.cc:507] Master 127.8.168.190:36627 requested a full tablet report, sending...
I20260812 06:19:28.849840  9254 ts_manager.cc:194] Registered new tserver with Master: 63c794cf0a8a420fa5987ead88a1a2ed (127.8.168.129:45297)
I20260812 06:19:28.850369  8866 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008662654s
I20260812 06:19:28.850703  9254 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40432
I20260812 06:19:28.856877  9254 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40434:
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:19:28.864842  9435 tablet_service.cc:1511] Processing CreateTablet for tablet e9fbee8500e2486d90ca7f49ffb64d8c (DEFAULT_TABLE table=heavy-update-compaction-test [id=7be7daf2ac524b0d9ecd3c510ba28346]), partition=
I20260812 06:19:28.865090  9435 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e9fbee8500e2486d90ca7f49ffb64d8c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:28.866967  9520 tablet_bootstrap.cc:492] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Bootstrap starting.
I20260812 06:19:28.867853  9520 tablet_bootstrap.cc:654] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:28.868731  9520 tablet_bootstrap.cc:492] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: No bootstrap required, opened a new log
I20260812 06:19:28.868800  9520 ts_tablet_manager.cc:1403] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:28.869129  9520 raft_consensus.cc:359] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63c794cf0a8a420fa5987ead88a1a2ed" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 45297 } }
I20260812 06:19:28.869223  9520 raft_consensus.cc:385] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:28.869251  9520 raft_consensus.cc:740] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 63c794cf0a8a420fa5987ead88a1a2ed, State: Initialized, Role: FOLLOWER
I20260812 06:19:28.869341  9520 consensus_queue.cc:260] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [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: "63c794cf0a8a420fa5987ead88a1a2ed" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 45297 } }
I20260812 06:19:28.869397  9520 raft_consensus.cc:399] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:28.869423  9520 raft_consensus.cc:493] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:28.869455  9520 raft_consensus.cc:3060] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:28.870095  9520 raft_consensus.cc:515] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63c794cf0a8a420fa5987ead88a1a2ed" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 45297 } }
I20260812 06:19:28.870249  9520 leader_election.cc:304] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [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: 63c794cf0a8a420fa5987ead88a1a2ed; no voters: 
I20260812 06:19:28.870474  9520 leader_election.cc:290] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:28.870587  9526 raft_consensus.cc:2804] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:28.870785  9520 ts_tablet_manager.cc:1434] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:28.870808  9497 heartbeater.cc:499] Master 127.8.168.190:36627 was elected leader, sending a full tablet report...
I20260812 06:19:28.870960  9526 raft_consensus.cc:697] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 1 LEADER]: Becoming Leader. State: Replica: 63c794cf0a8a420fa5987ead88a1a2ed, State: Running, Role: LEADER
I20260812 06:19:28.871088  9526 consensus_queue.cc:237] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [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: "63c794cf0a8a420fa5987ead88a1a2ed" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 45297 } }
I20260812 06:19:28.872339  9254 catalog_manager.cc:5719] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed reported cstate change: term changed from 0 to 1, leader changed from <none> to 63c794cf0a8a420fa5987ead88a1a2ed (127.8.168.129). New cstate: current_term: 1 leader_uuid: "63c794cf0a8a420fa5987ead88a1a2ed" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63c794cf0a8a420fa5987ead88a1a2ed" member_type: VOTER last_known_addr { host: "127.8.168.129" port: 45297 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:28.926561  8866 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.017s	sys 0.004s
I20260812 06:19:29.092165  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=23.023690
I20260812 06:19:29.244194  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.152s	user 0.122s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":862,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41182,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:29.244926  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): free 20290830 bytes of WAL
I20260812 06:19:29.245160  9386 log_reader.cc:385] T e9fbee8500e2486d90ca7f49ffb64d8c: removed 2 log segments from log reader
I20260812 06:19:29.245237  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000001 (ops 1-6)
I20260812 06:19:29.245280  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000002 (ops 7-10)
I20260812 06:19:29.250931  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:29.251458  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:29.276719  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.025s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:19:29.277179  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:29.287568  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.288079  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): 20513813 bytes on disk
I20260812 06:19:29.288575  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:19:29.289016  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:29.481475  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.192s	user 0.139s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815804,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":557,"lbm_read_time_us":11775,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26658,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":299,"threads_started":5,"update_count":2500}
I20260812 06:19:29.481951  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:29.530761  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.049s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18849,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.531251  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:29.541659  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.542230  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:29.685300  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.143s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":320,"lbm_read_time_us":11529,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25871,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:29.685815  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=11.118625
I20260812 06:19:29.716120  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.030s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12945,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:29.716554  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:29.730957  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4363,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.731529  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:29.850556  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.119s	user 0.111s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":809,"lbm_read_time_us":7724,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23378,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:19:29.851099  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=10.126437
I20260812 06:19:29.890637  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.039s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15208,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.891238  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:29.900807  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.901476  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:30.012411  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.111s	user 0.082s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":270,"lbm_read_time_us":7834,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20329,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":66048,"update_count":2000}
I20260812 06:19:30.012989  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=10.126437
I20260812 06:19:30.063181  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.050s	user 0.016s	sys 0.031s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17334,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.063690  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:30.073719  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.074163  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:30.224841  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.150s	user 0.116s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":10833,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21845,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:30.225407  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=10.126437
I20260812 06:19:30.269496  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.044s	user 0.008s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13476,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.269951  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:30.280100  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.280808  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:30.405470  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.124s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":8640,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22980,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2000}
I20260812 06:19:30.406126  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=10.126437
I20260812 06:19:30.449074  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.043s	user 0.033s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15609,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.449540  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:30.459434  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3787,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.460096  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:30.487874  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1565,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1371,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:30.488517  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): free 121006369 bytes of WAL
I20260812 06:19:30.488749  9386 log_reader.cc:385] T e9fbee8500e2486d90ca7f49ffb64d8c: removed 12 log segments from log reader
I20260812 06:19:30.488811  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000003 (ops 11-15)
I20260812 06:19:30.488857  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000004 (ops 16-20)
I20260812 06:19:30.488885  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000005 (ops 21-24)
I20260812 06:19:30.488916  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000006 (ops 25-29)
I20260812 06:19:30.488953  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000007 (ops 30-34)
I20260812 06:19:30.488983  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000008 (ops 35-39)
I20260812 06:19:30.489012  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000009 (ops 40-44)
I20260812 06:19:30.489039  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000010 (ops 45-49)
I20260812 06:19:30.489070  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000011 (ops 50-54)
I20260812 06:19:30.489101  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000012 (ops 55-59)
I20260812 06:19:30.489130  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000013 (ops 60-64)
I20260812 06:19:30.489149  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000014 (ops 65-69)
I20260812 06:19:30.514547  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:30.515061  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): 472 bytes on disk
I20260812 06:19:30.515762  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:30.516288  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=3.181125
I20260812 06:19:30.528821  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:30.529210  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:30.542192  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4827,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:30.542663  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:30.702179  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.159s	user 0.138s	sys 0.018s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5776,"lbm_read_time_us":11004,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30481,"lbm_writes_lt_1ms":643,"mutex_wait_us":2750,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:19:30.702759  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:30.745883  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.043s	user 0.027s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18608,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.746446  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:30.765588  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5490,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.766080  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:30.919636  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.153s	user 0.125s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":10888,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27636,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:19:30.920323  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:30.982640  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.062s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23539,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.983165  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:30.998158  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.998672  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:31.164113  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.165s	user 0.098s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":13042,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27416,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:31.164778  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=11.118625
I20260812 06:19:31.217638  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.053s	user 0.018s	sys 0.031s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19540,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:31.218079  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=3.181125
I20260812 06:19:31.230710  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4800070,"delete_count":0,"lbm_write_time_us":4811,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:19:31.231109  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.196750
I20260812 06:19:31.242100  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4046,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:19:31.242538  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:31.406862  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.164s	user 0.095s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815782,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":526,"lbm_read_time_us":11581,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26914,"lbm_writes_lt_1ms":543,"mutex_wait_us":288,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:31.407442  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:31.469233  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.061s	user 0.020s	sys 0.037s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22779,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.469787  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:31.479768  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.480206  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:31.649521  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.169s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":12314,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25450,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":59392,"update_count":2500}
I20260812 06:19:31.650063  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:31.708745  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.059s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19757,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.709285  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:31.724674  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.725168  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:31.898346  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.173s	user 0.113s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":12217,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28940,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:31.898905  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=11.118625
I20260812 06:19:31.929286  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.030s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12708,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:31.929847  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:31.942821  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4829,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.943645  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:31.981259  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.037s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1404,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2100,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:31.981948  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): 492 bytes on disk
I20260812 06:19:31.982380  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:31.982887  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=3.181125
I20260812 06:19:32.000372  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.017s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4143,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:32.000887  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): free 140885472 bytes of WAL
I20260812 06:19:32.001127  9386 log_reader.cc:385] T e9fbee8500e2486d90ca7f49ffb64d8c: removed 14 log segments from log reader
I20260812 06:19:32.001185  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000015 (ops 70-74)
I20260812 06:19:32.001242  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000016 (ops 75-78)
I20260812 06:19:32.001278  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000017 (ops 79-83)
I20260812 06:19:32.001300  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000018 (ops 84-88)
I20260812 06:19:32.001327  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000019 (ops 89-93)
I20260812 06:19:32.001356  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000020 (ops 94-98)
I20260812 06:19:32.001389  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000021 (ops 99-103)
I20260812 06:19:32.001417  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000022 (ops 104-108)
I20260812 06:19:32.001447  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000023 (ops 109-112)
I20260812 06:19:32.001474  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000024 (ops 113-117)
I20260812 06:19:32.001503  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000025 (ops 118-122)
I20260812 06:19:32.001535  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000026 (ops 123-127)
I20260812 06:19:32.001565  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000027 (ops 128-132)
I20260812 06:19:32.001593  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000028 (ops 133-136)
I20260812 06:19:32.032874  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:32.033342  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:32.048779  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.049248  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:32.058663  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3401,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:32.059118  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:32.283900  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.225s	user 0.141s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":572,"lbm_read_time_us":15725,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33116,"lbm_writes_lt_1ms":743,"mutex_wait_us":282,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:19:32.284469  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=18.063937
I20260812 06:19:32.356092  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.071s	user 0.025s	sys 0.028s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":25126,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:32.356609  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:32.366638  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.367130  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:32.559738  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.192s	user 0.097s	sys 0.094s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":746,"lbm_read_time_us":13576,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32270,"lbm_writes_lt_1ms":643,"mutex_wait_us":350,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3000}
I20260812 06:19:32.560298  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:32.604163  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.044s	user 0.029s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.604671  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:32.763351  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.159s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":591,"lbm_read_time_us":10083,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23996,"lbm_writes_lt_1ms":443,"mutex_wait_us":261,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:19:32.763897  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:32.816847  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.053s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19660,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.817332  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:32.827782  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.828329  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:33.013042  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.185s	user 0.090s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":10480,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27629,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:33.013592  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:33.062083  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.048s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21962,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.062634  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:33.074407  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4053,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.074833  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:33.217211  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.142s	user 0.107s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":682,"lbm_read_time_us":11631,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26226,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:19:33.217866  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=11.118625
I20260812 06:19:33.254356  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.036s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":15182,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:33.254937  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:33.267222  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.267722  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:33.399744  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.132s	user 0.093s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":715,"lbm_read_time_us":7170,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24797,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:33.400259  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=14.095187
I20260812 06:19:33.468523  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.068s	user 0.035s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":39126,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.469236  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:33.487074  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.018s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.487627  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:33.533524  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushMRSOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.046s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":1369,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1801,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:33.534173  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): 493 bytes on disk
I20260812 06:19:33.534740  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: UndoDeltaBlockGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:33.535342  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=3.181125
I20260812 06:19:33.546839  8866 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.620s	user 1.724s	sys 0.135s
I20260812 06:19:33.548297  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:33.548830  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c): free 129773837 bytes of WAL
I20260812 06:19:33.549043  9386 log_reader.cc:385] T e9fbee8500e2486d90ca7f49ffb64d8c: removed 13 log segments from log reader
I20260812 06:19:33.549088  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000029 (ops 137-141)
I20260812 06:19:33.549124  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000030 (ops 142-146)
I20260812 06:19:33.549161  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000031 (ops 147-151)
I20260812 06:19:33.549199  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000032 (ops 152-156)
I20260812 06:19:33.549230  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000033 (ops 157-161)
I20260812 06:19:33.549261  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000034 (ops 162-166)
I20260812 06:19:33.549291  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000035 (ops 167-171)
I20260812 06:19:33.549320  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000036 (ops 172-176)
I20260812 06:19:33.549350  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000037 (ops 177-181)
I20260812 06:19:33.549379  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000038 (ops 182-186)
I20260812 06:19:33.549408  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000039 (ops 187-190)
I20260812 06:19:33.549437  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000040 (ops 191-195)
I20260812 06:19:33.549466  9386 log.cc:1079] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: Deleting log segment in path: /tmp/dist-test-taskuiR_iy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515563391114-8866-0/minicluster-data/ts-0-root/wals/e9fbee8500e2486d90ca7f49ffb64d8c/wal-000000041 (ops 196-200)
I20260812 06:19:33.570420  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: LogGCOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:33.570927  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=2.188937
I20260812 06:19:33.579874  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: FlushDeltaMemStoresOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3481,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.580365  9498 maintenance_manager.cc:419] P 63c794cf0a8a420fa5987ead88a1a2ed: Scheduling MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c): perf score=1.000000
I20260812 06:19:33.607805  8866 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.061s	user 0.001s	sys 0.000s
I20260812 06:19:33.608292  8866 tablet_server.cc:179] TabletServer@127.8.168.129:0 shutting down...
I20260812 06:19:33.710724  9386 maintenance_manager.cc:643] P 63c794cf0a8a420fa5987ead88a1a2ed: MajorDeltaCompactionOp(e9fbee8500e2486d90ca7f49ffb64d8c) complete. Timing: real 0.130s	user 0.093s	sys 0.037s Metrics: {"cfile_cache_hit":619,"cfile_cache_hit_bytes":25885748,"cfile_cache_miss":115,"cfile_cache_miss_bytes":7134985,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1062,"lbm_read_time_us":2980,"lbm_reads_lt_1ms":143,"lbm_write_time_us":30953,"lbm_writes_lt_1ms":743,"mutex_wait_us":288,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:19:33.711295  8866 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:33.711649  8866 tablet_replica.cc:333] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed: stopping tablet replica
I20260812 06:19:33.711769  8866 raft_consensus.cc:2243] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.711930  8866 raft_consensus.cc:2272] T e9fbee8500e2486d90ca7f49ffb64d8c P 63c794cf0a8a420fa5987ead88a1a2ed [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.725131  8866 tablet_server.cc:196] TabletServer@127.8.168.129:0 shutdown complete.
I20260812 06:19:33.767438  8866 master.cc:562] Master@127.8.168.190:36627 shutting down...
I20260812 06:19:33.770399  8866 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.770560  8866 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.770608  8866 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8de71669f0744c5b919331e41401264c: stopping tablet replica
I20260812 06:19:33.782608  8866 master.cc:584] Master@127.8.168.190:36627 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5129 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10456 ms total)

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