[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:17.765743 27792 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.36.62:36293
I20260812 06:18:17.766690 27792 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:17.767305 27792 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:17.773150 27802 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:17.773191 27804 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.773274 27792 server_base.cc:1061] running on GCE node
W20260812 06:18:17.775157 27801 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.775700 27792 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:17.775815 27792 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:17.775853 27792 hybrid_clock.cc:648] HybridClock initialized: now 1786515497775851 us; error 0 us; skew 500 ppm
I20260812 06:18:17.777745 27792 webserver.cc:533] Webserver started at http://127.27.36.62:40883/ using document root <none> and password file <none>
I20260812 06:18:17.778226 27792 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:17.778291 27792 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:17.778522 27792 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:17.781157 27792 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/master-0-root/instance:
uuid: "ad74fefd80a64561a08702e5a1eb8e9e"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-1vmg"
I20260812 06:18:17.784789 27792 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:17.786685 27812 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.787675 27792 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:17.787766 27792 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/master-0-root
uuid: "ad74fefd80a64561a08702e5a1eb8e9e"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-1vmg"
I20260812 06:18:17.787839 27792 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:17.810717 27792 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:17.811232 27792 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:17.811352 27792 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:17.817942 27792 rpc_server.cc:307] RPC server started. Bound to: 127.27.36.62:36293
I20260812 06:18:17.817971 27903 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.36.62:36293 every 8 connection(s)
I20260812 06:18:17.820003 27906 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:17.825014 27906 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: Bootstrap starting.
I20260812 06:18:17.827229 27906 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:17.828022 27906 log.cc:826] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:17.829491 27906 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: No bootstrap required, opened a new log
I20260812 06:18:17.832082 27906 raft_consensus.cc:359] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad74fefd80a64561a08702e5a1eb8e9e" member_type: VOTER }
I20260812 06:18:17.832245 27906 raft_consensus.cc:385] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:17.832312 27906 raft_consensus.cc:740] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ad74fefd80a64561a08702e5a1eb8e9e, State: Initialized, Role: FOLLOWER
I20260812 06:18:17.832872 27906 consensus_queue.cc:260] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [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: "ad74fefd80a64561a08702e5a1eb8e9e" member_type: VOTER }
I20260812 06:18:17.833019 27906 raft_consensus.cc:399] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:17.833082 27906 raft_consensus.cc:493] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:17.833204 27906 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:17.833882 27906 raft_consensus.cc:515] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad74fefd80a64561a08702e5a1eb8e9e" member_type: VOTER }
I20260812 06:18:17.834282 27906 leader_election.cc:304] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [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: ad74fefd80a64561a08702e5a1eb8e9e; no voters: 
I20260812 06:18:17.834551 27906 leader_election.cc:290] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:17.834664 27912 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:17.834863 27912 raft_consensus.cc:697] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 1 LEADER]: Becoming Leader. State: Replica: ad74fefd80a64561a08702e5a1eb8e9e, State: Running, Role: LEADER
I20260812 06:18:17.835276 27912 consensus_queue.cc:237] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [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: "ad74fefd80a64561a08702e5a1eb8e9e" member_type: VOTER }
I20260812 06:18:17.835400 27906 sys_catalog.cc:565] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:17.836966 27917 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [sys.catalog]: SysCatalogTable state changed. Reason: New leader ad74fefd80a64561a08702e5a1eb8e9e. Latest consensus state: current_term: 1 leader_uuid: "ad74fefd80a64561a08702e5a1eb8e9e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad74fefd80a64561a08702e5a1eb8e9e" member_type: VOTER } }
I20260812 06:18:17.836997 27915 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ad74fefd80a64561a08702e5a1eb8e9e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad74fefd80a64561a08702e5a1eb8e9e" member_type: VOTER } }
I20260812 06:18:17.837075 27917 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:17.837090 27915 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:17.837581 27792 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:17.839476 27936 catalog_manager.cc:1594] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:17.839548 27936 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:17.839607 27931 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:17.840446 27931 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:17.844821 27931 catalog_manager.cc:1383] Generated new cluster ID: e1945b92432a4a6dbc2aa52469e57339
I20260812 06:18:17.844868 27931 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:17.872614 27931 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:17.873360 27931 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:17.880811 27931 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: Generated new TSK 0
I20260812 06:18:17.881328 27931 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:17.901989 27792 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:17.904407 27942 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:17.904488 27950 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.904667 27792 server_base.cc:1061] running on GCE node
W20260812 06:18:17.904742 27945 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.904964 27792 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:17.905004 27792 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:17.905025 27792 hybrid_clock.cc:648] HybridClock initialized: now 1786515497905025 us; error 0 us; skew 500 ppm
I20260812 06:18:17.905854 27792 webserver.cc:533] Webserver started at http://127.27.36.1:35725/ using document root <none> and password file <none>
I20260812 06:18:17.906005 27792 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:17.906052 27792 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:17.906126 27792 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:17.906456 27792 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/instance:
uuid: "e5201d4b69924979903ab9f468b74e2b"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-1vmg"
I20260812 06:18:17.907845 27792 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:17.908710 27957 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.908919 27792 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:17.908979 27792 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root
uuid: "e5201d4b69924979903ab9f468b74e2b"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-1vmg"
I20260812 06:18:17.909037 27792 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:17.929821 27792 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:17.930145 27792 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:17.930537 27792 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:17.931344 27792 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:17.931396 27792 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.931435 27792 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:17.931465 27792 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.937436 27792 rpc_server.cc:307] RPC server started. Bound to: 127.27.36.1:40229
I20260812 06:18:17.937476 28068 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.36.1:40229 every 8 connection(s)
I20260812 06:18:17.951053 28069 heartbeater.cc:344] Connected to a master server at 127.27.36.62:36293
I20260812 06:18:17.951305 28069 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:17.951722 28069 heartbeater.cc:507] Master 127.27.36.62:36293 requested a full tablet report, sending...
I20260812 06:18:17.953115 27838 ts_manager.cc:194] Registered new tserver with Master: e5201d4b69924979903ab9f468b74e2b (127.27.36.1:40229)
I20260812 06:18:17.953495 27792 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015498421s
I20260812 06:18:17.954578 27838 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53628
I20260812 06:18:17.965399 27838 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53642:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:17.977695 28007 tablet_service.cc:1511] Processing CreateTablet for tablet 79ac14f1abca49b8bd26bdc5587cf662 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4eccd8a3adb442b9b43af027ebc932e7]), partition=
I20260812 06:18:17.978120 28007 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 79ac14f1abca49b8bd26bdc5587cf662. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:17.980171 28090 tablet_bootstrap.cc:492] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Bootstrap starting.
I20260812 06:18:17.981253 28090 tablet_bootstrap.cc:654] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:17.982404 28090 tablet_bootstrap.cc:492] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: No bootstrap required, opened a new log
I20260812 06:18:17.982512 28090 ts_tablet_manager.cc:1403] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:17.983002 28090 raft_consensus.cc:359] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5201d4b69924979903ab9f468b74e2b" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 40229 } }
I20260812 06:18:17.983112 28090 raft_consensus.cc:385] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:17.983188 28090 raft_consensus.cc:740] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e5201d4b69924979903ab9f468b74e2b, State: Initialized, Role: FOLLOWER
I20260812 06:18:17.983322 28090 consensus_queue.cc:260] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [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: "e5201d4b69924979903ab9f468b74e2b" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 40229 } }
I20260812 06:18:17.983405 28090 raft_consensus.cc:399] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:17.983445 28090 raft_consensus.cc:493] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:17.983489 28090 raft_consensus.cc:3060] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:17.984404 28090 raft_consensus.cc:515] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5201d4b69924979903ab9f468b74e2b" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 40229 } }
I20260812 06:18:17.984549 28090 leader_election.cc:304] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [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: e5201d4b69924979903ab9f468b74e2b; no voters: 
I20260812 06:18:17.984763 28090 leader_election.cc:290] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:17.984920 28094 raft_consensus.cc:2804] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:17.985080 28090 ts_tablet_manager.cc:1434] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:17.985188 28094 raft_consensus.cc:697] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 1 LEADER]: Becoming Leader. State: Replica: e5201d4b69924979903ab9f468b74e2b, State: Running, Role: LEADER
I20260812 06:18:17.985270 28069 heartbeater.cc:499] Master 127.27.36.62:36293 was elected leader, sending a full tablet report...
I20260812 06:18:17.985622 28094 consensus_queue.cc:237] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [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: "e5201d4b69924979903ab9f468b74e2b" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 40229 } }
I20260812 06:18:17.988294 27836 catalog_manager.cc:5719] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b reported cstate change: term changed from 0 to 1, leader changed from <none> to e5201d4b69924979903ab9f468b74e2b (127.27.36.1). New cstate: current_term: 1 leader_uuid: "e5201d4b69924979903ab9f468b74e2b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5201d4b69924979903ab9f468b74e2b" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 40229 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:18.044147 27792 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.018s	sys 0.007s
I20260812 06:18:18.188558 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=19.054940
I20260812 06:18:18.359320 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.170s	user 0.120s	sys 0.048s Metrics: {"bytes_written":12799771,"cfile_init":1,"compiler_manager_pool.queue_time_us":235,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":986,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44776,"lbm_writes_lt_1ms":769,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":309504,"thread_start_us":144,"threads_started":1,"update_count":1560}
I20260812 06:18:18.360461 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling LogGCOp(79ac14f1abca49b8bd26bdc5587cf662): free 20743880 bytes of WAL
I20260812 06:18:18.360754 27965 log_reader.cc:385] T 79ac14f1abca49b8bd26bdc5587cf662: removed 2 log segments from log reader
I20260812 06:18:18.360812 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000001 (ops 1-6)
I20260812 06:18:18.360908 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000002 (ops 7-11)
I20260812 06:18:18.365681 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: LogGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:18.366027 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=3.181125
I20260812 06:18:18.389374 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.023s	user 0.014s	sys 0.007s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":6022,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:18:18.389757 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662): 16411396 bytes on disk
I20260812 06:18:18.390278 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.390671 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.196750
I20260812 06:18:18.398120 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.007s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":2719,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:18:18.398490 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:18.557549 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.159s	user 0.095s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774763,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":735,"lbm_read_time_us":11145,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27303,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":299,"threads_started":5,"update_count":2500}
I20260812 06:18:18.558007 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:18.602865 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.045s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.603320 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:18.612651 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.613020 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:18.731212 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.118s	user 0.090s	sys 0.025s 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":1218,"lbm_read_time_us":8349,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20576,"lbm_writes_lt_1ms":443,"mutex_wait_us":319,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:18.731709 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:18.772317 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.040s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14053,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.772766 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:18.781912 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.782297 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:18.900892 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.118s	user 0.093s	sys 0.023s 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":604,"lbm_read_time_us":8625,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22469,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.901336 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:18.941054 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.040s	user 0.004s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16095,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.941555 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:18.956233 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.015s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.956625 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:19.079574 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.123s	user 0.106s	sys 0.017s 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":538,"lbm_read_time_us":9340,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23065,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:19.080034 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:19.124001 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.044s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16566,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.124473 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:19.134080 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.134460 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:19.259035 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.124s	user 0.084s	sys 0.040s 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":976,"lbm_read_time_us":9838,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19426,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:19.259799 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:19.297925 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.038s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14182,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.298391 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:19.308058 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.308420 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:19.424511 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.116s	user 0.104s	sys 0.012s 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":237,"lbm_read_time_us":8721,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22070,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:18:19.424999 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:19.459026 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.034s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13181,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.459460 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:19.471202 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.471706 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:19.503199 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1269,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1427,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:19.504069 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling LogGCOp(79ac14f1abca49b8bd26bdc5587cf662): free 112239269 bytes of WAL
I20260812 06:18:19.504307 27965 log_reader.cc:385] T 79ac14f1abca49b8bd26bdc5587cf662: removed 11 log segments from log reader
I20260812 06:18:19.504355 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000003 (ops 12-16)
I20260812 06:18:19.504382 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000004 (ops 17-21)
I20260812 06:18:19.504398 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000005 (ops 22-26)
I20260812 06:18:19.504431 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000006 (ops 27-30)
I20260812 06:18:19.504463 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000007 (ops 31-35)
I20260812 06:18:19.504495 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000008 (ops 36-40)
I20260812 06:18:19.504527 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000009 (ops 41-45)
I20260812 06:18:19.504558 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000010 (ops 46-50)
I20260812 06:18:19.504590 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000011 (ops 51-55)
I20260812 06:18:19.504621 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000012 (ops 56-60)
I20260812 06:18:19.504652 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000013 (ops 61-65)
I20260812 06:18:19.524712 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: LogGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:19.525141 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662): 462 bytes on disk
I20260812 06:18:19.525677 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.526209 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=3.181125
I20260812 06:18:19.542714 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":6690,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:19.543138 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:19.553081 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3602,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.553571 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:19.706887 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.153s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":6125,"lbm_read_time_us":10589,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30240,"lbm_writes_lt_1ms":643,"mutex_wait_us":2068,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:19.707453 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=14.095187
I20260812 06:18:19.755712 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.048s	user 0.025s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.756186 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:19.765925 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.766469 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:19.897167 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.131s	user 0.110s	sys 0.019s 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":231,"lbm_read_time_us":9016,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27206,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:19.897616 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=11.118625
I20260812 06:18:19.934785 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.037s	user 0.031s	sys 0.003s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":16278,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.935279 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:19.947420 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.947999 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:20.064316 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.116s	user 0.098s	sys 0.018s 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":635,"lbm_read_time_us":8771,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22809,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31232,"update_count":2000}
I20260812 06:18:20.064764 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:20.113330 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.048s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.113888 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:20.124771 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.125277 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:20.270279 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.145s	user 0.116s	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":223,"lbm_read_time_us":10798,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25847,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:20.271049 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:20.310354 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.039s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16442,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.310830 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:20.325937 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.015s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5892,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.326391 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:20.445434 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.119s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":351,"lbm_read_time_us":7549,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23320,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.446049 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:20.475256 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.028s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12315,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.475687 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:20.486416 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.486979 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:20.601667 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.114s	user 0.102s	sys 0.013s 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":295,"lbm_read_time_us":9436,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20291,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:20.602274 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:20.645860 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.043s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16667,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:20.646378 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:20.657660 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.658084 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:20.774183 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.116s	user 0.084s	sys 0.032s 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":139,"lbm_read_time_us":9095,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22371,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.776466 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:20.814492 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.038s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12463,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.815043 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:20.824694 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.825062 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:20.864446 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.039s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1250,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:20.865198 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling LogGCOp(79ac14f1abca49b8bd26bdc5587cf662): free 133024367 bytes of WAL
I20260812 06:18:20.865406 27965 log_reader.cc:385] T 79ac14f1abca49b8bd26bdc5587cf662: removed 13 log segments from log reader
I20260812 06:18:20.865449 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000014 (ops 66-70)
I20260812 06:18:20.865475 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000015 (ops 71-75)
I20260812 06:18:20.865509 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000016 (ops 76-80)
I20260812 06:18:20.865542 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000017 (ops 81-84)
I20260812 06:18:20.865574 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000018 (ops 85-89)
I20260812 06:18:20.865617 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000019 (ops 90-94)
I20260812 06:18:20.865639 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000020 (ops 95-99)
I20260812 06:18:20.865660 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000021 (ops 100-104)
I20260812 06:18:20.865681 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000022 (ops 105-109)
I20260812 06:18:20.865702 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000023 (ops 110-114)
I20260812 06:18:20.865732 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000024 (ops 115-119)
I20260812 06:18:20.865756 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000025 (ops 120-124)
I20260812 06:18:20.865788 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000026 (ops 125-129)
I20260812 06:18:20.890944 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: LogGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:20.891302 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662): 482 bytes on disk
I20260812 06:18:20.891690 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662) 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:18:20.892194 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=3.181125
I20260812 06:18:20.904263 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:20.904635 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:20.916678 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.917065 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:21.104898 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.188s	user 0.132s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":498,"lbm_read_time_us":13579,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30860,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:21.105333 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=14.095187
I20260812 06:18:21.149746 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20030,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.150310 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:21.275480 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.125s	user 0.087s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":189,"lbm_read_time_us":8779,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20891,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.276117 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=11.118625
I20260812 06:18:21.311013 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14920,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.311753 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:21.338580 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5129,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.339103 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:21.348585 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.349119 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:21.520896 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.172s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":536,"lbm_read_time_us":10298,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25530,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:21.521441 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=14.095187
I20260812 06:18:21.566841 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.045s	user 0.022s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19167,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.567302 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:21.582361 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.582827 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:21.734215 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.151s	user 0.091s	sys 0.049s 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":159,"lbm_read_time_us":8676,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29205,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":63232,"update_count":2500}
I20260812 06:18:21.734838 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=14.095187
I20260812 06:18:21.784682 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.050s	user 0.021s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21545,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.785171 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:21.795938 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.796352 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:21.927711 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.131s	user 0.103s	sys 0.027s 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":953,"lbm_read_time_us":8755,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28095,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:21.928334 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=11.118625
I20260812 06:18:21.966814 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.038s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15455,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.968098 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:21.979568 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.980008 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:21.989038 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3351,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.989415 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:22.126873 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.137s	user 0.093s	sys 0.044s 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":553,"lbm_read_time_us":9748,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27435,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":2500}
I20260812 06:18:22.128049 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=10.126437
I20260812 06:18:22.156191 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.028s	user 0.015s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12077,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:22.156638 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=2.188937
I20260812 06:18:22.167550 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.168202 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:22.197225 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushMRSOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.029s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":146,"dirs.run_wall_time_us":1170,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3817,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:22.197872 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling LogGCOp(79ac14f1abca49b8bd26bdc5587cf662): free 120553690 bytes of WAL
I20260812 06:18:22.198098 27965 log_reader.cc:385] T 79ac14f1abca49b8bd26bdc5587cf662: removed 12 log segments from log reader
I20260812 06:18:22.198155 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000027 (ops 130-134)
I20260812 06:18:22.198199 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000028 (ops 135-138)
I20260812 06:18:22.198233 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000029 (ops 139-143)
I20260812 06:18:22.198262 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000030 (ops 144-148)
I20260812 06:18:22.198290 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000031 (ops 149-152)
I20260812 06:18:22.198319 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000032 (ops 153-157)
I20260812 06:18:22.198349 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000033 (ops 158-162)
I20260812 06:18:22.198380 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000034 (ops 163-167)
I20260812 06:18:22.198407 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000035 (ops 168-172)
I20260812 06:18:22.198436 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000036 (ops 173-177)
I20260812 06:18:22.198463 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000037 (ops 178-182)
I20260812 06:18:22.198491 27965 log.cc:1079] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/79ac14f1abca49b8bd26bdc5587cf662/wal-000000038 (ops 183-187)
I20260812 06:18:22.222976 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: LogGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:22.223402 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662): 471 bytes on disk
I20260812 06:18:22.223865 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: UndoDeltaBlockGCOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.224458 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=4.173312
I20260812 06:18:22.237831 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":6071825,"delete_count":0,"lbm_write_time_us":5475,"lbm_writes_lt_1ms":151,"reinsert_count":0,"update_count":740}
I20260812 06:18:22.238168 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:22.245548 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2133453,"delete_count":0,"lbm_write_time_us":2091,"lbm_writes_lt_1ms":55,"reinsert_count":0,"update_count":260}
I20260812 06:18:22.245894 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=1.000000
I20260812 06:18:22.402236 27792 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.358s	user 1.604s	sys 0.112s
I20260812 06:18:22.405098 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: MajorDeltaCompactionOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.159s	user 0.131s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877293,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1964,"lbm_read_time_us":11535,"lbm_reads_lt_1ms":670,"lbm_write_time_us":31045,"lbm_writes_lt_1ms":643,"mutex_wait_us":752,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:18:22.405617 28071 maintenance_manager.cc:419] P e5201d4b69924979903ab9f468b74e2b: Scheduling FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662): perf score=14.095187
I20260812 06:18:22.428687 27792 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.026s	user 0.002s	sys 0.000s
I20260812 06:18:22.429600 27792 tablet_server.cc:179] TabletServer@127.27.36.1:0 shutting down...
I20260812 06:18:22.442252 27965 maintenance_manager.cc:643] P e5201d4b69924979903ab9f468b74e2b: FlushDeltaMemStoresOp(79ac14f1abca49b8bd26bdc5587cf662) complete. Timing: real 0.036s	user 0.030s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16256,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:22.442684 27792 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:22.443048 27792 tablet_replica.cc:333] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b: stopping tablet replica
I20260812 06:18:22.443243 27792 raft_consensus.cc:2243] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:22.443435 27792 raft_consensus.cc:2272] T 79ac14f1abca49b8bd26bdc5587cf662 P e5201d4b69924979903ab9f468b74e2b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:22.448567 27792 tablet_server.cc:196] TabletServer@127.27.36.1:0 shutdown complete.
I20260812 06:18:22.454154 27792 master.cc:562] Master@127.27.36.62:36293 shutting down...
I20260812 06:18:22.457324 27792 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:22.457444 27792 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:22.457505 27792 tablet_replica.cc:333] T 00000000000000000000000000000000 P ad74fefd80a64561a08702e5a1eb8e9e: stopping tablet replica
I20260812 06:18:22.469201 27792 master.cc:584] Master@127.27.36.62:36293 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4783 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:22.548007 27792 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.36.62:36653
I20260812 06:18:22.548359 27792 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.550150 28121 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:22.550209 28125 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:22.550235 27792 server_base.cc:1061] running on GCE node
W20260812 06:18:22.550320 28120 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:22.550503 27792 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.550546 27792 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:22.550566 27792 hybrid_clock.cc:648] HybridClock initialized: now 1786515502550566 us; error 0 us; skew 500 ppm
I20260812 06:18:22.551373 27792 webserver.cc:533] Webserver started at http://127.27.36.62:46751/ using document root <none> and password file <none>
I20260812 06:18:22.551525 27792 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.551580 27792 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.551656 27792 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.552011 27792 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/master-0-root/instance:
uuid: "df1c306aed084f3280a1048e3c2953f3"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-1vmg"
I20260812 06:18:22.553395 27792 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:22.554207 28137 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.554437 27792 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:22.554505 27792 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/master-0-root
uuid: "df1c306aed084f3280a1048e3c2953f3"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-1vmg"
I20260812 06:18:22.554577 27792 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:22.560968 27792 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.561249 27792 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.564937 27792 rpc_server.cc:307] RPC server started. Bound to: 127.27.36.62:36653
I20260812 06:18:22.578312 28217 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.36.62:36653 every 8 connection(s)
I20260812 06:18:22.578765 28218 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:22.580436 28218 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3: Bootstrap starting.
I20260812 06:18:22.581127 28218 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.581983 28218 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3: No bootstrap required, opened a new log
I20260812 06:18:22.582337 28218 raft_consensus.cc:359] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df1c306aed084f3280a1048e3c2953f3" member_type: VOTER }
I20260812 06:18:22.582413 28218 raft_consensus.cc:385] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.582439 28218 raft_consensus.cc:740] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: df1c306aed084f3280a1048e3c2953f3, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.582535 28218 consensus_queue.cc:260] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [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: "df1c306aed084f3280a1048e3c2953f3" member_type: VOTER }
I20260812 06:18:22.582592 28218 raft_consensus.cc:399] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.582618 28218 raft_consensus.cc:493] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.582654 28218 raft_consensus.cc:3060] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.583290 28218 raft_consensus.cc:515] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df1c306aed084f3280a1048e3c2953f3" member_type: VOTER }
I20260812 06:18:22.583397 28218 leader_election.cc:304] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [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: df1c306aed084f3280a1048e3c2953f3; no voters: 
I20260812 06:18:22.583526 28218 leader_election.cc:290] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.583647 28221 raft_consensus.cc:2804] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.583834 28221 raft_consensus.cc:697] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 1 LEADER]: Becoming Leader. State: Replica: df1c306aed084f3280a1048e3c2953f3, State: Running, Role: LEADER
I20260812 06:18:22.583943 28218 sys_catalog.cc:565] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:22.583967 28221 consensus_queue.cc:237] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [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: "df1c306aed084f3280a1048e3c2953f3" member_type: VOTER }
I20260812 06:18:22.584389 28222 sys_catalog.cc:455] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "df1c306aed084f3280a1048e3c2953f3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df1c306aed084f3280a1048e3c2953f3" member_type: VOTER } }
I20260812 06:18:22.584425 28224 sys_catalog.cc:455] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader df1c306aed084f3280a1048e3c2953f3. Latest consensus state: current_term: 1 leader_uuid: "df1c306aed084f3280a1048e3c2953f3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df1c306aed084f3280a1048e3c2953f3" member_type: VOTER } }
I20260812 06:18:22.584568 28224 sys_catalog.cc:458] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.584599 28222 sys_catalog.cc:458] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.585057 28230 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:22.585807 28230 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:22.585978 27792 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:22.587419 28230 catalog_manager.cc:1383] Generated new cluster ID: 15459eaa201e4c6d82f31a9f06c336f3
I20260812 06:18:22.587472 28230 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:22.609804 28230 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:22.610278 28230 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:22.619105 28230 catalog_manager.cc:6092] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3: Generated new TSK 0
I20260812 06:18:22.619234 28230 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:22.650295 27792 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.652169 28256 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:22.652259 28254 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:22.652199 28249 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:22.652304 27792 server_base.cc:1061] running on GCE node
I20260812 06:18:22.652550 27792 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.652602 27792 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:22.652619 27792 hybrid_clock.cc:648] HybridClock initialized: now 1786515502652618 us; error 0 us; skew 500 ppm
I20260812 06:18:22.653419 27792 webserver.cc:533] Webserver started at http://127.27.36.1:41639/ using document root <none> and password file <none>
I20260812 06:18:22.653566 27792 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.653625 27792 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.653705 27792 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.654066 27792 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/instance:
uuid: "9f8aa4a829b74e8eaa7dfd41f678849a"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-1vmg"
I20260812 06:18:22.655547 27792 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:22.656396 28271 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.656591 27792 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:22.656665 27792 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root
uuid: "9f8aa4a829b74e8eaa7dfd41f678849a"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-1vmg"
I20260812 06:18:22.656731 27792 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:22.661500 27792 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.661787 27792 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.662034 27792 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:22.662575 27792 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:22.662626 27792 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.662670 27792 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:22.662700 27792 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.666594 27792 rpc_server.cc:307] RPC server started. Bound to: 127.27.36.1:34201
I20260812 06:18:22.666621 28370 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.36.1:34201 every 8 connection(s)
I20260812 06:18:22.671003 28372 heartbeater.cc:344] Connected to a master server at 127.27.36.62:36653
I20260812 06:18:22.671098 28372 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:22.671327 28372 heartbeater.cc:507] Master 127.27.36.62:36653 requested a full tablet report, sending...
I20260812 06:18:22.671896 28162 ts_manager.cc:194] Registered new tserver with Master: 9f8aa4a829b74e8eaa7dfd41f678849a (127.27.36.1:34201)
I20260812 06:18:22.672554 27792 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005526821s
I20260812 06:18:22.672577 28162 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50838
I20260812 06:18:22.678632 28162 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50854:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:22.686664 28313 tablet_service.cc:1511] Processing CreateTablet for tablet 64f3642bd4fd41b9aefaef00fc44ca42 (DEFAULT_TABLE table=heavy-update-compaction-test [id=19ed55a709624ddda710a51e80c15386]), partition=
I20260812 06:18:22.686928 28313 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 64f3642bd4fd41b9aefaef00fc44ca42. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:22.688779 28386 tablet_bootstrap.cc:492] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Bootstrap starting.
I20260812 06:18:22.689664 28386 tablet_bootstrap.cc:654] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.690621 28386 tablet_bootstrap.cc:492] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: No bootstrap required, opened a new log
I20260812 06:18:22.690691 28386 ts_tablet_manager.cc:1403] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:22.691092 28386 raft_consensus.cc:359] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f8aa4a829b74e8eaa7dfd41f678849a" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 34201 } }
I20260812 06:18:22.691179 28386 raft_consensus.cc:385] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.691205 28386 raft_consensus.cc:740] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9f8aa4a829b74e8eaa7dfd41f678849a, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.691310 28386 consensus_queue.cc:260] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [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: "9f8aa4a829b74e8eaa7dfd41f678849a" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 34201 } }
I20260812 06:18:22.691395 28386 raft_consensus.cc:399] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.691425 28386 raft_consensus.cc:493] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.691458 28386 raft_consensus.cc:3060] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.692260 28386 raft_consensus.cc:515] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f8aa4a829b74e8eaa7dfd41f678849a" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 34201 } }
I20260812 06:18:22.692399 28386 leader_election.cc:304] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [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: 9f8aa4a829b74e8eaa7dfd41f678849a; no voters: 
I20260812 06:18:22.692559 28386 leader_election.cc:290] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.692667 28390 raft_consensus.cc:2804] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.692839 28390 raft_consensus.cc:697] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 1 LEADER]: Becoming Leader. State: Replica: 9f8aa4a829b74e8eaa7dfd41f678849a, State: Running, Role: LEADER
I20260812 06:18:22.692842 28386 ts_tablet_manager.cc:1434] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:22.692876 28372 heartbeater.cc:499] Master 127.27.36.62:36653 was elected leader, sending a full tablet report...
I20260812 06:18:22.693017 28390 consensus_queue.cc:237] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [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: "9f8aa4a829b74e8eaa7dfd41f678849a" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 34201 } }
I20260812 06:18:22.694240 28162 catalog_manager.cc:5719] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a reported cstate change: term changed from 0 to 1, leader changed from <none> to 9f8aa4a829b74e8eaa7dfd41f678849a (127.27.36.1). New cstate: current_term: 1 leader_uuid: "9f8aa4a829b74e8eaa7dfd41f678849a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f8aa4a829b74e8eaa7dfd41f678849a" member_type: VOTER last_known_addr { host: "127.27.36.1" port: 34201 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:22.747159 27792 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.013s	sys 0.008s
I20260812 06:18:22.917579 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=23.023690
I20260812 06:18:23.073850 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.156s	user 0.099s	sys 0.055s Metrics: {"bytes_written":13127966,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":167,"dirs.run_wall_time_us":797,"drs_written":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43735,"lbm_writes_lt_1ms":887,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"update_count":1600}
I20260812 06:18:23.074712 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42): 20924070 bytes on disk
I20260812 06:18:23.075163 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.075630 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42): free 20743880 bytes of WAL
I20260812 06:18:23.075830 28278 log_reader.cc:385] T 64f3642bd4fd41b9aefaef00fc44ca42: removed 2 log segments from log reader
I20260812 06:18:23.075876 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000001 (ops 1-6)
I20260812 06:18:23.075960 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000002 (ops 7-11)
I20260812 06:18:23.080734 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.005s	user 0.001s	sys 0.002s Metrics: {}
I20260812 06:18:23.081110 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:23.096328 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.015s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":3279,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:23.096738 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:23.106411 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3592,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.106822 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:23.260644 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.154s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24446495,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":588,"lbm_read_time_us":13469,"lbm_reads_lt_1ms":559,"lbm_write_time_us":26979,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":314,"threads_started":5,"update_count":2450}
I20260812 06:18:23.261240 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:23.319294 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.058s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26063,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.319778 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:23.345762 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.346215 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:23.356735 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.357192 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:23.542462 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.185s	user 0.149s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959184,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":413,"lbm_read_time_us":11373,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39925,"lbm_writes_lt_1ms":643,"mutex_wait_us":118,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":42368,"update_count":3000}
I20260812 06:18:23.543068 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:23.600214 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.057s	user 0.024s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25005,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.600718 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=3.181125
I20260812 06:18:23.612677 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:23.613103 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:23.628023 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5601,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.628561 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:23.779412 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.151s	user 0.102s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959172,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":458,"lbm_read_time_us":12537,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29727,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":3000}
I20260812 06:18:23.779901 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:23.820358 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.040s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17790,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.820761 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:23.829941 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.830386 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:23.968423 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.138s	user 0.109s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":9299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25702,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:23.968876 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=12.110812
I20260812 06:18:24.019030 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":14030496,"delete_count":0,"lbm_write_time_us":22474,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":343,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1710}
I20260812 06:18:24.019496 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.196750
I20260812 06:18:24.033749 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2789860,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:18:24.034142 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.042596 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3244,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.043000 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:24.207242 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.164s	user 0.092s	sys 0.069s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24856726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":77,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29339,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:24.207851 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:24.258463 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.050s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18231,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.258986 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.268671 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.269207 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:24.298447 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.029s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1244,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1363,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:24.299131 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42): free 132571324 bytes of WAL
I20260812 06:18:24.299355 28278 log_reader.cc:385] T 64f3642bd4fd41b9aefaef00fc44ca42: removed 13 log segments from log reader
I20260812 06:18:24.299403 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000003 (ops 12-16)
I20260812 06:18:24.299443 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000004 (ops 17-20)
I20260812 06:18:24.299474 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000005 (ops 21-25)
I20260812 06:18:24.299506 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000006 (ops 26-30)
I20260812 06:18:24.299538 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000007 (ops 31-35)
I20260812 06:18:24.299569 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000008 (ops 36-40)
I20260812 06:18:24.299611 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000009 (ops 41-45)
I20260812 06:18:24.299644 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000010 (ops 46-50)
I20260812 06:18:24.299669 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000011 (ops 51-55)
I20260812 06:18:24.299700 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000012 (ops 56-60)
I20260812 06:18:24.299729 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000013 (ops 61-65)
I20260812 06:18:24.299773 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000014 (ops 66-70)
I20260812 06:18:24.299804 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000015 (ops 71-74)
I20260812 06:18:24.326351 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:24.326790 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=3.181125
I20260812 06:18:24.344507 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6323,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:24.344888 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42): 482 bytes on disk
I20260812 06:18:24.345240 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42) 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:18:24.345655 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.354104 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3135,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.354427 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:24.555363 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.201s	user 0.146s	sys 0.051s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061703,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":321,"lbm_read_time_us":15600,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33907,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":109,"threads_started":1,"update_count":3500}
I20260812 06:18:24.556936 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=15.087375
I20260812 06:18:24.610400 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.053s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16820138,"delete_count":0,"lbm_write_time_us":21144,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:24.611050 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.628952 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.629431 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.639179 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.639605 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:24.799829 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.160s	user 0.124s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959167,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":213,"lbm_read_time_us":12049,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30683,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":3000}
I20260812 06:18:24.800424 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:24.854099 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.052s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23292,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.854591 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.879933 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.880336 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:24.889736 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.008s	sys 0.000s 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:18:24.890100 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:25.052335 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.162s	user 0.128s	sys 0.034s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959187,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":127,"lbm_read_time_us":13497,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31106,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":3000}
I20260812 06:18:25.052870 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:25.094214 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.041s	user 0.019s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17320,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.094748 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:25.104089 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3541,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.104554 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:25.239068 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.134s	user 0.101s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":700,"lbm_read_time_us":9097,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25284,"lbm_writes_lt_1ms":543,"mutex_wait_us":328,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:25.239540 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=12.110812
I20260812 06:18:25.287288 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.048s	user 0.015s	sys 0.028s Metrics: {"bytes_written":14112550,"delete_count":0,"lbm_write_time_us":18506,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":346,"reinsert_count":0,"update_count":1720}
I20260812 06:18:25.287722 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.196750
I20260812 06:18:25.303195 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.015s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2707809,"delete_count":0,"lbm_write_time_us":2903,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:25.303617 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:25.312093 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3161,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.312559 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:25.484508 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.172s	user 0.115s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24856729,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1851,"lbm_read_time_us":11399,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26863,"lbm_writes_lt_1ms":543,"mutex_wait_us":1590,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.485080 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:25.538709 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.053s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18814,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.539196 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:25.548650 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3661,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.549017 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:25.577462 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193508,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1356,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:25.578152 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42): free 121006409 bytes of WAL
I20260812 06:18:25.578382 28278 log_reader.cc:385] T 64f3642bd4fd41b9aefaef00fc44ca42: removed 12 log segments from log reader
I20260812 06:18:25.578430 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000016 (ops 75-79)
I20260812 06:18:25.578460 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000017 (ops 80-84)
I20260812 06:18:25.578477 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000018 (ops 85-89)
I20260812 06:18:25.578507 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000019 (ops 90-94)
I20260812 06:18:25.578549 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000020 (ops 95-99)
I20260812 06:18:25.578583 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000021 (ops 100-104)
I20260812 06:18:25.578613 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000022 (ops 105-109)
I20260812 06:18:25.578644 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000023 (ops 110-114)
I20260812 06:18:25.578675 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000024 (ops 115-119)
I20260812 06:18:25.578706 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000025 (ops 120-124)
I20260812 06:18:25.578735 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000026 (ops 125-128)
I20260812 06:18:25.578765 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000027 (ops 129-133)
I20260812 06:18:25.600805 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:25.601154 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42): 462 bytes on disk
I20260812 06:18:25.601517 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.601987 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=3.181125
I20260812 06:18:25.616763 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.015s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:25.617159 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:25.625936 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3315,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.626310 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:25.839131 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.213s	user 0.132s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061704,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1361,"lbm_read_time_us":15271,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37199,"lbm_writes_lt_1ms":743,"mutex_wait_us":1898,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:18:25.839989 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=18.063937
I20260812 06:18:25.908165 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.068s	user 0.034s	sys 0.027s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":30058,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.908707 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=3.181125
I20260812 06:18:25.925974 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7112,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:25.926365 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:25.934983 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.008s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3188,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.935350 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:26.116297 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.181s	user 0.148s	sys 0.032s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33061592,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":142,"lbm_read_time_us":12712,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37208,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":3500}
I20260812 06:18:26.116935 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:26.179368 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.062s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25358,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"mutex_wait_us":29,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.179867 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=3.181125
I20260812 06:18:26.196439 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6880,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:26.196825 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:26.205473 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3302,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.205839 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:26.359010 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.153s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959174,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":878,"lbm_read_time_us":12589,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29951,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:26.359509 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:26.404556 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.045s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.405083 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:26.416203 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.416781 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:26.566200 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.149s	user 0.108s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856652,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":103,"lbm_read_time_us":9308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26009,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2500}
I20260812 06:18:26.566628 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:26.606200 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.039s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17843,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.606609 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:26.763481 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.157s	user 0.094s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20754122,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":122,"lbm_read_time_us":9810,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25982,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:18:26.763948 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=14.095187
I20260812 06:18:26.805778 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.042s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.806326 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:26.816447 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.010s	user 0.004s	sys 0.004s 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:18:26.817054 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:26.850020 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushMRSOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":160,"dirs.run_wall_time_us":1179,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1995,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:26.850755 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42): free 120553636 bytes of WAL
I20260812 06:18:26.850996 28278 log_reader.cc:385] T 64f3642bd4fd41b9aefaef00fc44ca42: removed 12 log segments from log reader
I20260812 06:18:26.851043 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000028 (ops 134-138)
I20260812 06:18:26.851079 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000029 (ops 139-142)
I20260812 06:18:26.851121 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000030 (ops 143-147)
I20260812 06:18:26.851148 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000031 (ops 148-152)
I20260812 06:18:26.851179 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000032 (ops 153-156)
I20260812 06:18:26.851212 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000033 (ops 157-161)
I20260812 06:18:26.851243 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000034 (ops 162-166)
I20260812 06:18:26.851272 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000035 (ops 167-171)
I20260812 06:18:26.851302 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000036 (ops 172-176)
I20260812 06:18:26.851333 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000037 (ops 177-181)
I20260812 06:18:26.851364 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000038 (ops 182-186)
I20260812 06:18:26.851395 28278 log.cc:1079] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: Deleting log segment in path: /tmp/dist-test-taskVPCkiS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497755058-27792-0/minicluster-data/ts-0-root/wals/64f3642bd4fd41b9aefaef00fc44ca42/wal-000000039 (ops 187-191)
I20260812 06:18:26.874025 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: LogGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:18:26.874487 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:26.893230 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.019s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3970,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.893682 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=2.188937
I20260812 06:18:26.903123 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.903622 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42): 462 bytes on disk
I20260812 06:18:26.904063 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: UndoDeltaBlockGCOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.904645 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=1.000000
I20260812 06:18:27.023665 27792 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.276s	user 1.580s	sys 0.119s
I20260812 06:18:27.110733 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: MajorDeltaCompactionOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.206s	user 0.129s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061714,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1210,"lbm_read_time_us":15721,"lbm_reads_lt_1ms":770,"lbm_write_time_us":31509,"lbm_writes_lt_1ms":743,"mutex_wait_us":537,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15104,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:18:27.111303 28373 maintenance_manager.cc:419] P 9f8aa4a829b74e8eaa7dfd41f678849a: Scheduling FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42): perf score=10.126437
I20260812 06:18:27.117875 27792 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.001s	sys 0.000s
I20260812 06:18:27.118294 27792 tablet_server.cc:179] TabletServer@127.27.36.1:0 shutting down...
I20260812 06:18:27.150146 28278 maintenance_manager.cc:643] P 9f8aa4a829b74e8eaa7dfd41f678849a: FlushDeltaMemStoresOp(64f3642bd4fd41b9aefaef00fc44ca42) complete. Timing: real 0.037s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16143,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.150648 27792 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:27.150841 27792 tablet_replica.cc:333] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a: stopping tablet replica
I20260812 06:18:27.151021 27792 raft_consensus.cc:2243] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:27.151173 27792 raft_consensus.cc:2272] T 64f3642bd4fd41b9aefaef00fc44ca42 P 9f8aa4a829b74e8eaa7dfd41f678849a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:27.154716 27792 tablet_server.cc:196] TabletServer@127.27.36.1:0 shutdown complete.
I20260812 06:18:27.166704 27792 master.cc:562] Master@127.27.36.62:36653 shutting down...
I20260812 06:18:27.169802 27792 raft_consensus.cc:2243] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:27.169932 27792 raft_consensus.cc:2272] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:27.169998 27792 tablet_replica.cc:333] T 00000000000000000000000000000000 P df1c306aed084f3280a1048e3c2953f3: stopping tablet replica
I20260812 06:18:27.181893 27792 master.cc:584] Master@127.27.36.62:36653 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4707 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9491 ms total)

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