[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:24.188922 21883 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.94.254:33307
I20260812 06:19:24.190251 21883 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:24.191052 21883 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:24.198519 21883 server_base.cc:1061] running on GCE node
W20260812 06:19:24.198782 21892 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:24.198760 21890 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:24.199062 21898 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:24.199642 21883 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:24.199774 21883 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:24.199826 21883 hybrid_clock.cc:648] HybridClock initialized: now 1786515564199822 us; error 0 us; skew 500 ppm
I20260812 06:19:24.201931 21883 webserver.cc:533] Webserver started at http://127.21.94.254:46045/ using document root <none> and password file <none>
I20260812 06:19:24.202620 21883 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:24.202708 21883 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:24.203063 21883 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:24.205070 21883 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/master-0-root/instance:
uuid: "0c67dffac6bf40b593e35355b36e1400"
format_stamp: "Formatted at 2026-08-12 06:19:24 on dist-test-slave-nfb5"
I20260812 06:19:24.209368 21883 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:19:24.212047 21904 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:24.213435 21883 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:24.213689 21883 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/master-0-root
uuid: "0c67dffac6bf40b593e35355b36e1400"
format_stamp: "Formatted at 2026-08-12 06:19:24 on dist-test-slave-nfb5"
I20260812 06:19:24.213822 21883 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:24.236971 21883 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:24.237866 21883 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:24.238090 21883 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:24.247664 21883 rpc_server.cc:307] RPC server started. Bound to: 127.21.94.254:33307
I20260812 06:19:24.247675 21987 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.94.254:33307 every 8 connection(s)
I20260812 06:19:24.250577 21989 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:24.257426 21989 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: Bootstrap starting.
I20260812 06:19:24.260535 21989 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:24.261788 21989 log.cc:826] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:24.264194 21989 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: No bootstrap required, opened a new log
I20260812 06:19:24.267674 21989 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c67dffac6bf40b593e35355b36e1400" member_type: VOTER }
I20260812 06:19:24.267891 21989 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:24.267993 21989 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0c67dffac6bf40b593e35355b36e1400, State: Initialized, Role: FOLLOWER
I20260812 06:19:24.268797 21989 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [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: "0c67dffac6bf40b593e35355b36e1400" member_type: VOTER }
I20260812 06:19:24.268998 21989 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:24.269083 21989 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:24.269251 21989 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:24.270272 21989 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c67dffac6bf40b593e35355b36e1400" member_type: VOTER }
I20260812 06:19:24.270850 21989 leader_election.cc:304] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [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: 0c67dffac6bf40b593e35355b36e1400; no voters: 
I20260812 06:19:24.271348 21989 leader_election.cc:290] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:24.271523 21993 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:24.271835 21993 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 1 LEADER]: Becoming Leader. State: Replica: 0c67dffac6bf40b593e35355b36e1400, State: Running, Role: LEADER
I20260812 06:19:24.272334 21993 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [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: "0c67dffac6bf40b593e35355b36e1400" member_type: VOTER }
I20260812 06:19:24.272632 21989 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:24.274748 21994 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0c67dffac6bf40b593e35355b36e1400" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c67dffac6bf40b593e35355b36e1400" member_type: VOTER } }
I20260812 06:19:24.274796 21997 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0c67dffac6bf40b593e35355b36e1400. Latest consensus state: current_term: 1 leader_uuid: "0c67dffac6bf40b593e35355b36e1400" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c67dffac6bf40b593e35355b36e1400" member_type: VOTER } }
I20260812 06:19:24.274893 21994 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:24.274951 21997 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:24.275420 21883 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:24.277763 22015 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:24.277830 22015 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:24.277915 22014 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:24.278710 22014 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:24.285172 22014 catalog_manager.cc:1383] Generated new cluster ID: b25719850b384ebbab4cc6ffb741bc0e
I20260812 06:19:24.285266 22014 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:24.307426 22014 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:24.308890 22014 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:24.321097 22014 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: Generated new TSK 0
I20260812 06:19:24.322165 22014 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:24.340695 21883 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:24.344283 22028 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:24.344375 22026 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:24.344295 22021 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:24.344729 21883 server_base.cc:1061] running on GCE node
I20260812 06:19:24.345010 21883 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:24.345078 21883 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:24.345112 21883 hybrid_clock.cc:648] HybridClock initialized: now 1786515564345112 us; error 0 us; skew 500 ppm
I20260812 06:19:24.346311 21883 webserver.cc:533] Webserver started at http://127.21.94.193:36357/ using document root <none> and password file <none>
I20260812 06:19:24.346534 21883 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:24.346617 21883 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:24.346709 21883 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:24.347270 21883 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/instance:
uuid: "64e0b239423c4fe3baf7dee6d35264d1"
format_stamp: "Formatted at 2026-08-12 06:19:24 on dist-test-slave-nfb5"
I20260812 06:19:24.349011 21883 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:24.350103 22038 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:24.350396 21883 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:24.350481 21883 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root
uuid: "64e0b239423c4fe3baf7dee6d35264d1"
format_stamp: "Formatted at 2026-08-12 06:19:24 on dist-test-slave-nfb5"
I20260812 06:19:24.350579 21883 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:24.369467 21883 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:24.370091 21883 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:24.370795 21883 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:24.372323 21883 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:24.372388 21883 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:24.372478 21883 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:24.372519 21883 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:24.380611 21883 rpc_server.cc:307] RPC server started. Bound to: 127.21.94.193:45751
I20260812 06:19:24.380811 22135 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.94.193:45751 every 8 connection(s)
I20260812 06:19:24.392808 22137 heartbeater.cc:344] Connected to a master server at 127.21.94.254:33307
I20260812 06:19:24.393142 22137 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:24.393702 22137 heartbeater.cc:507] Master 127.21.94.254:33307 requested a full tablet report, sending...
I20260812 06:19:24.395586 21936 ts_manager.cc:194] Registered new tserver with Master: 64e0b239423c4fe3baf7dee6d35264d1 (127.21.94.193:45751)
I20260812 06:19:24.396175 21883 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014661098s
I20260812 06:19:24.397320 21936 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34386
I20260812 06:19:24.407181 21936 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34398:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:24.426507 22079 tablet_service.cc:1511] Processing CreateTablet for tablet 4886d9e64542458f9fe902b8733b7788 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ebd85c92fdc94aec9c57209fa7285f4e]), partition=
I20260812 06:19:24.427172 22079 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4886d9e64542458f9fe902b8733b7788. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:24.430603 22153 tablet_bootstrap.cc:492] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Bootstrap starting.
I20260812 06:19:24.431949 22153 tablet_bootstrap.cc:654] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:24.433490 22153 tablet_bootstrap.cc:492] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: No bootstrap required, opened a new log
I20260812 06:19:24.433609 22153 ts_tablet_manager.cc:1403] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:24.434150 22153 raft_consensus.cc:359] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64e0b239423c4fe3baf7dee6d35264d1" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45751 } }
I20260812 06:19:24.434276 22153 raft_consensus.cc:385] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:24.434301 22153 raft_consensus.cc:740] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 64e0b239423c4fe3baf7dee6d35264d1, State: Initialized, Role: FOLLOWER
I20260812 06:19:24.434463 22153 consensus_queue.cc:260] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [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: "64e0b239423c4fe3baf7dee6d35264d1" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45751 } }
I20260812 06:19:24.434567 22153 raft_consensus.cc:399] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:24.434654 22153 raft_consensus.cc:493] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:24.434715 22153 raft_consensus.cc:3060] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:24.435621 22153 raft_consensus.cc:515] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64e0b239423c4fe3baf7dee6d35264d1" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45751 } }
I20260812 06:19:24.435783 22153 leader_election.cc:304] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [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: 64e0b239423c4fe3baf7dee6d35264d1; no voters: 
I20260812 06:19:24.436044 22153 leader_election.cc:290] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:24.436146 22158 raft_consensus.cc:2804] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:24.436331 22158 raft_consensus.cc:697] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 1 LEADER]: Becoming Leader. State: Replica: 64e0b239423c4fe3baf7dee6d35264d1, State: Running, Role: LEADER
I20260812 06:19:24.436435 22153 ts_tablet_manager.cc:1434] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:24.436582 22158 consensus_queue.cc:237] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [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: "64e0b239423c4fe3baf7dee6d35264d1" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45751 } }
I20260812 06:19:24.436760 22137 heartbeater.cc:499] Master 127.21.94.254:33307 was elected leader, sending a full tablet report...
I20260812 06:19:24.439796 21936 catalog_manager.cc:5719] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 64e0b239423c4fe3baf7dee6d35264d1 (127.21.94.193). New cstate: current_term: 1 leader_uuid: "64e0b239423c4fe3baf7dee6d35264d1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64e0b239423c4fe3baf7dee6d35264d1" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45751 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:24.514881 21883 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.024s	sys 0.008s
I20260812 06:19:24.632190 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushMRSOp(4886d9e64542458f9fe902b8733b7788): perf score=11.117440
I20260812 06:19:24.808377 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushMRSOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.176s	user 0.119s	sys 0.053s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":287,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":791,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43409,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":196,"threads_started":1,"update_count":1450}
I20260812 06:19:24.810274 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling LogGCOp(4886d9e64542458f9fe902b8733b7788): free 8725963 bytes of WAL
I20260812 06:19:24.810796 22044 log_reader.cc:385] T 4886d9e64542458f9fe902b8733b7788: removed 1 log segments from log reader
I20260812 06:19:24.810949 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000001 (ops 1-6)
I20260812 06:19:24.813730 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: LogGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:24.814199 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788): 8616791 bytes on disk
I20260812 06:19:24.815451 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":128,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.816100 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:24.833324 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.833907 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:24.995963 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.162s	user 0.128s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20221071,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":873,"lbm_read_time_us":8633,"lbm_reads_lt_1ms":450,"lbm_write_time_us":29854,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":382,"threads_started":5,"update_count":1950}
I20260812 06:19:24.996613 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:25.039004 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.042s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16531,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.039566 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:25.165597 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.126s	user 0.110s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":251,"lbm_read_time_us":9400,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23382,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":1500}
I20260812 06:19:25.166235 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:25.211772 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18491,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.212368 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:25.225426 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.226085 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:25.371719 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.145s	user 0.126s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":10444,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28383,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:25.372470 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:25.429033 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.056s	user 0.033s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23322,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.429577 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:25.441164 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.442091 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:25.580070 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.138s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":989,"lbm_read_time_us":10344,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25531,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":48512,"update_count":2000}
I20260812 06:19:25.580884 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:25.636504 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.055s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19115,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:19:25.637082 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:25.649448 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.650204 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:25.803925 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.153s	user 0.128s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":368,"lbm_read_time_us":11057,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31465,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":63104,"update_count":2000}
I20260812 06:19:25.804589 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:25.860988 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.056s	user 0.019s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20699,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.861690 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:25.874272 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.874850 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:26.039633 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.165s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":13048,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28440,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:19:26.040704 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:26.101188 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.060s	user 0.032s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.101795 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:26.113865 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.114481 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:26.275143 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.160s	user 0.144s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":313,"lbm_read_time_us":11792,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29719,"lbm_writes_lt_1ms":443,"mutex_wait_us":109,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:26.275799 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:26.331236 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.055s	user 0.021s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20804,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.331876 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:26.344856 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.345605 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushMRSOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:26.379570 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushMRSOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":1517,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1835,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:26.380708 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling LogGCOp(4886d9e64542458f9fe902b8733b7788): free 124257233 bytes of WAL
I20260812 06:19:26.380991 22044 log_reader.cc:385] T 4886d9e64542458f9fe902b8733b7788: removed 12 log segments from log reader
I20260812 06:19:26.381067 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000002 (ops 7-11)
I20260812 06:19:26.381136 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000003 (ops 12-16)
I20260812 06:19:26.381196 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000004 (ops 17-21)
I20260812 06:19:26.381239 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000005 (ops 22-26)
I20260812 06:19:26.381280 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000006 (ops 27-31)
I20260812 06:19:26.381319 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000007 (ops 32-36)
I20260812 06:19:26.381359 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000008 (ops 37-41)
I20260812 06:19:26.381398 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000009 (ops 42-46)
I20260812 06:19:26.381438 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000010 (ops 47-50)
I20260812 06:19:26.381477 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000011 (ops 51-55)
I20260812 06:19:26.381517 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000012 (ops 56-60)
I20260812 06:19:26.381556 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000013 (ops 61-65)
I20260812 06:19:26.410391 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: LogGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:26.411020 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788): 473 bytes on disk
I20260812 06:19:26.411552 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:26.412088 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=3.181125
I20260812 06:19:26.426447 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5586,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:26.427008 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:26.438122 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:26.438537 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:26.652719 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.214s	user 0.155s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":950,"lbm_read_time_us":14813,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41684,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:19:26.653568 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:26.710006 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.056s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23534,"lbm_writes_lt_1ms":403,"mutex_wait_us":2,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.710635 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:26.724138 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.724833 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:26.913611 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.189s	user 0.142s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1425,"lbm_read_time_us":12067,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34803,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:26.917431 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:26.977433 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.060s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22810,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.978097 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:26.991797 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.992509 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:27.214843 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.222s	user 0.164s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":438,"lbm_read_time_us":16111,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36877,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:19:27.215607 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:27.262137 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.046s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20940,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.262814 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:27.442305 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.179s	user 0.130s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":622,"lbm_read_time_us":13318,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29990,"lbm_writes_lt_1ms":443,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:19:27.443095 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:27.487740 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.044s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17778,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.488437 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:27.501611 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.502379 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:27.666208 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.164s	user 0.122s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":10539,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32232,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.666785 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:27.710453 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.043s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16761,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.711269 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:27.837885 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.126s	user 0.102s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528784,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":218,"lbm_read_time_us":6909,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23655,"lbm_writes_lt_1ms":343,"mutex_wait_us":43,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.838778 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:27.882704 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.044s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18875,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:27.883430 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:28.016073 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.132s	user 0.100s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1258,"lbm_read_time_us":9736,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21300,"lbm_writes_lt_1ms":343,"mutex_wait_us":88,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":1500}
I20260812 06:19:28.017046 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=10.126437
I20260812 06:19:28.061903 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.045s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17602,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.062682 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:28.076004 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.076660 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushMRSOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:28.113796 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushMRSOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.037s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1321,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2493,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:28.114894 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling LogGCOp(4886d9e64542458f9fe902b8733b7788): free 124710247 bytes of WAL
I20260812 06:19:28.115218 22044 log_reader.cc:385] T 4886d9e64542458f9fe902b8733b7788: removed 12 log segments from log reader
I20260812 06:19:28.115294 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000014 (ops 66-70)
I20260812 06:19:28.115355 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000015 (ops 71-75)
I20260812 06:19:28.115392 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000016 (ops 76-80)
I20260812 06:19:28.115432 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000017 (ops 81-85)
I20260812 06:19:28.115470 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000018 (ops 86-90)
I20260812 06:19:28.115517 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000019 (ops 91-95)
I20260812 06:19:28.115556 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000020 (ops 96-100)
I20260812 06:19:28.115593 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000021 (ops 101-105)
I20260812 06:19:28.115630 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000022 (ops 106-110)
I20260812 06:19:28.115667 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000023 (ops 111-115)
I20260812 06:19:28.115705 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000024 (ops 116-120)
I20260812 06:19:28.115741 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000025 (ops 121-125)
I20260812 06:19:28.146193 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: LogGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:28.146816 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788): 473 bytes on disk
I20260812 06:19:28.147433 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:19:28.148351 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:28.170432 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4307779,"delete_count":0,"lbm_write_time_us":7899,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:19:28.171216 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling LogGCOp(4886d9e64542458f9fe902b8733b7788): free 12017991 bytes of WAL
I20260812 06:19:28.171490 22044 log_reader.cc:385] T 4886d9e64542458f9fe902b8733b7788: removed 1 log segments from log reader
I20260812 06:19:28.171566 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000026 (ops 126-130)
I20260812 06:19:28.174218 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: LogGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:28.174587 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:28.187794 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:28.188395 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:28.422513 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.234s	user 0.151s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836370,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":732,"lbm_read_time_us":15054,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39938,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:19:28.423344 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:28.485056 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.061s	user 0.028s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27234,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.485673 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:28.499773 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.500502 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:28.725498 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.225s	user 0.137s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":450,"lbm_read_time_us":14670,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35543,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:28.726287 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:28.784759 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.058s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22070,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.785368 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:28.803947 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.018s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.804781 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:28.985193 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.180s	user 0.138s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":751,"lbm_read_time_us":12004,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34298,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:19:28.988737 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=11.118625
I20260812 06:19:29.029414 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.040s	user 0.017s	sys 0.020s Metrics: {"bytes_written":13456167,"delete_count":0,"lbm_write_time_us":17036,"lbm_writes_lt_1ms":331,"reinsert_count":0,"update_count":1640}
I20260812 06:19:29.030097 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=1.196750
I20260812 06:19:29.054198 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.024s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3584,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:19:29.054950 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:29.073000 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.018s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.073825 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:29.259563 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.186s	user 0.139s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733816,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":585,"lbm_read_time_us":12239,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35201,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:29.260365 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:29.320907 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.060s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23352,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:29.321548 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:29.335857 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.336580 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:29.521159 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.184s	user 0.158s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":11693,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37934,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:29.521836 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=11.118625
I20260812 06:19:29.558421 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15897,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:29.559641 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:29.579010 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7029,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.579602 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:29.733668 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.154s	user 0.125s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":11411,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31734,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:19:29.734587 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=11.118625
I20260812 06:19:29.791114 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.056s	user 0.037s	sys 0.019s Metrics: {"bytes_written":12635684,"delete_count":0,"lbm_write_time_us":20301,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1540}
I20260812 06:19:29.791921 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:29.811224 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.019s	user 0.015s	sys 0.004s Metrics: {"bytes_written":3774458,"delete_count":0,"lbm_write_time_us":7179,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:29.812026 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushMRSOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:29.859768 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushMRSOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.047s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1222,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1703,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:29.860775 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling LogGCOp(4886d9e64542458f9fe902b8733b7788): free 121006656 bytes of WAL
I20260812 06:19:29.861032 22044 log_reader.cc:385] T 4886d9e64542458f9fe902b8733b7788: removed 12 log segments from log reader
I20260812 06:19:29.861085 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000027 (ops 131-135)
I20260812 06:19:29.861129 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000028 (ops 136-140)
I20260812 06:19:29.861162 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000029 (ops 141-145)
I20260812 06:19:29.861192 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000030 (ops 146-150)
I20260812 06:19:29.861227 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000031 (ops 151-155)
I20260812 06:19:29.861258 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000032 (ops 156-160)
I20260812 06:19:29.861285 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000033 (ops 161-165)
I20260812 06:19:29.861315 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000034 (ops 166-170)
I20260812 06:19:29.861342 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000035 (ops 171-174)
I20260812 06:19:29.861375 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000036 (ops 175-179)
I20260812 06:19:29.861409 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000037 (ops 180-184)
I20260812 06:19:29.861438 22044 log.cc:1079] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/4886d9e64542458f9fe902b8733b7788/wal-000000038 (ops 185-189)
I20260812 06:19:29.890403 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: LogGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:29.891112 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:29.921954 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.031s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.922566 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:29.934481 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.935086 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788): 472 bytes on disk
I20260812 06:19:29.935557 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: UndoDeltaBlockGCOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:29.936105 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:30.171343 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.235s	user 0.137s	sys 0.088s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836367,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2420,"lbm_read_time_us":15660,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40204,"lbm_writes_lt_1ms":643,"mutex_wait_us":1741,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:19:30.172211 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=14.095187
I20260812 06:19:30.255510 21883 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.740s	user 2.210s	sys 0.113s
I20260812 06:19:30.259965 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.087s	user 0.023s	sys 0.052s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":34158,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.260509 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788): perf score=2.188937
I20260812 06:19:30.278954 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: FlushDeltaMemStoresOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":500}
I20260812 06:19:30.279650 22140 maintenance_manager.cc:419] P 64e0b239423c4fe3baf7dee6d35264d1: Scheduling MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788): perf score=1.000000
I20260812 06:19:30.349061 21883 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.002s	sys 0.000s
I20260812 06:19:30.349931 21883 tablet_server.cc:179] TabletServer@127.21.94.193:0 shutting down...
I20260812 06:19:30.434938 22044 maintenance_manager.cc:643] P 64e0b239423c4fe3baf7dee6d35264d1: MajorDeltaCompactionOp(4886d9e64542458f9fe902b8733b7788) complete. Timing: real 0.155s	user 0.098s	sys 0.056s Metrics: {"cfile_cache_hit":241,"cfile_cache_hit_bytes":9848010,"cfile_cache_miss":291,"cfile_cache_miss_bytes":14885716,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"lbm_read_time_us":9165,"lbm_reads_lt_1ms":323,"lbm_write_time_us":29748,"lbm_writes_lt_1ms":543,"mutex_wait_us":102,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":183040,"update_count":2500}
I20260812 06:19:30.436116 21883 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:30.436625 21883 tablet_replica.cc:333] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1: stopping tablet replica
I20260812 06:19:30.436918 21883 raft_consensus.cc:2243] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:30.437222 21883 raft_consensus.cc:2272] T 4886d9e64542458f9fe902b8733b7788 P 64e0b239423c4fe3baf7dee6d35264d1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:30.454435 21883 tablet_server.cc:196] TabletServer@127.21.94.193:0 shutdown complete.
I20260812 06:19:30.483286 21883 master.cc:562] Master@127.21.94.254:33307 shutting down...
I20260812 06:19:30.487912 21883 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:30.488193 21883 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:30.488299 21883 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0c67dffac6bf40b593e35355b36e1400: stopping tablet replica
I20260812 06:19:30.501212 21883 master.cc:584] Master@127.21.94.254:33307 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6406 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:30.609324 21883 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.94.254:35189
I20260812 06:19:30.609841 21883 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:30.612535 21883 server_base.cc:1061] running on GCE node
W20260812 06:19:30.612624 22188 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:30.612633 22186 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:30.612795 22190 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:30.613119 21883 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:30.613168 21883 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:30.613184 21883 hybrid_clock.cc:648] HybridClock initialized: now 1786515570613185 us; error 0 us; skew 500 ppm
I20260812 06:19:30.614246 21883 webserver.cc:533] Webserver started at http://127.21.94.254:38775/ using document root <none> and password file <none>
I20260812 06:19:30.614449 21883 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:30.614526 21883 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:30.614625 21883 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:30.615172 21883 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/master-0-root/instance:
uuid: "853f156c409d4696b5f0d30b78005257"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-nfb5"
I20260812 06:19:30.616835 21883 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:30.617841 22200 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:30.618180 21883 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:30.618283 21883 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/master-0-root
uuid: "853f156c409d4696b5f0d30b78005257"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-nfb5"
I20260812 06:19:30.618381 21883 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:30.629803 21883 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:30.630213 21883 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:30.635154 21883 rpc_server.cc:307] RPC server started. Bound to: 127.21.94.254:35189
I20260812 06:19:30.638239 22279 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.94.254:35189 every 8 connection(s)
I20260812 06:19:30.638855 22280 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:30.641134 22280 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257: Bootstrap starting.
I20260812 06:19:30.642071 22280 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:30.643304 22280 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257: No bootstrap required, opened a new log
I20260812 06:19:30.643778 22280 raft_consensus.cc:359] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "853f156c409d4696b5f0d30b78005257" member_type: VOTER }
I20260812 06:19:30.643880 22280 raft_consensus.cc:385] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:30.643936 22280 raft_consensus.cc:740] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 853f156c409d4696b5f0d30b78005257, State: Initialized, Role: FOLLOWER
I20260812 06:19:30.644151 22280 consensus_queue.cc:260] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [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: "853f156c409d4696b5f0d30b78005257" member_type: VOTER }
I20260812 06:19:30.644229 22280 raft_consensus.cc:399] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:30.644299 22280 raft_consensus.cc:493] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:30.644361 22280 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:30.645143 22280 raft_consensus.cc:515] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "853f156c409d4696b5f0d30b78005257" member_type: VOTER }
I20260812 06:19:30.645300 22280 leader_election.cc:304] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [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: 853f156c409d4696b5f0d30b78005257; no voters: 
I20260812 06:19:30.645532 22280 leader_election.cc:290] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:30.645692 22285 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:30.645952 22285 raft_consensus.cc:697] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 1 LEADER]: Becoming Leader. State: Replica: 853f156c409d4696b5f0d30b78005257, State: Running, Role: LEADER
I20260812 06:19:30.646095 22285 consensus_queue.cc:237] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [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: "853f156c409d4696b5f0d30b78005257" member_type: VOTER }
I20260812 06:19:30.646130 22280 sys_catalog.cc:565] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:30.646634 22286 sys_catalog.cc:455] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "853f156c409d4696b5f0d30b78005257" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "853f156c409d4696b5f0d30b78005257" member_type: VOTER } }
I20260812 06:19:30.646665 22287 sys_catalog.cc:455] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 853f156c409d4696b5f0d30b78005257. Latest consensus state: current_term: 1 leader_uuid: "853f156c409d4696b5f0d30b78005257" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "853f156c409d4696b5f0d30b78005257" member_type: VOTER } }
I20260812 06:19:30.646806 22286 sys_catalog.cc:458] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:30.646828 22287 sys_catalog.cc:458] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:30.647513 22292 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:30.648245 22292 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:30.648434 21883 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:30.650215 22292 catalog_manager.cc:1383] Generated new cluster ID: 27a085cc82624b2b998f91c288446ef5
I20260812 06:19:30.650279 22292 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:30.656836 22292 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:30.657410 22292 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:30.667426 22292 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257: Generated new TSK 0
I20260812 06:19:30.667659 22292 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:30.681046 21883 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:30.683446 22308 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:30.683533 22310 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:30.683601 22313 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:30.683542 21883 server_base.cc:1061] running on GCE node
I20260812 06:19:30.683871 21883 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:30.683914 21883 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:30.683933 21883 hybrid_clock.cc:648] HybridClock initialized: now 1786515570683932 us; error 0 us; skew 500 ppm
I20260812 06:19:30.684878 21883 webserver.cc:533] Webserver started at http://127.21.94.193:42443/ using document root <none> and password file <none>
I20260812 06:19:30.685036 21883 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:30.685087 21883 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:30.685179 21883 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:30.685618 21883 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/instance:
uuid: "927c435634314255a68b2909026be60e"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-nfb5"
I20260812 06:19:30.687291 21883 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:30.688350 22319 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:30.688710 21883 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:30.688781 21883 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root
uuid: "927c435634314255a68b2909026be60e"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-nfb5"
I20260812 06:19:30.688880 21883 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:30.699460 21883 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:30.699920 21883 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:30.700271 21883 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:30.700830 21883 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:30.700896 21883 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:30.700977 21883 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:30.701026 21883 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:30.706001 21883 rpc_server.cc:307] RPC server started. Bound to: 127.21.94.193:45851
I20260812 06:19:30.706558 22419 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.94.193:45851 every 8 connection(s)
I20260812 06:19:30.714681 22420 heartbeater.cc:344] Connected to a master server at 127.21.94.254:35189
I20260812 06:19:30.714833 22420 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:30.715197 22420 heartbeater.cc:507] Master 127.21.94.254:35189 requested a full tablet report, sending...
I20260812 06:19:30.715940 22224 ts_manager.cc:194] Registered new tserver with Master: 927c435634314255a68b2909026be60e (127.21.94.193:45851)
I20260812 06:19:30.716647 21883 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009952252s
I20260812 06:19:30.716764 22224 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60510
I20260812 06:19:30.724267 22224 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60516:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:30.734047 22364 tablet_service.cc:1511] Processing CreateTablet for tablet 02363bf1cfc446fdb92fd4e05951d4ba (DEFAULT_TABLE table=heavy-update-compaction-test [id=2c8723a8c0f346f79026a0cf3b0cab0e]), partition=
I20260812 06:19:30.734349 22364 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 02363bf1cfc446fdb92fd4e05951d4ba. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:30.736877 22436 tablet_bootstrap.cc:492] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Bootstrap starting.
I20260812 06:19:30.737890 22436 tablet_bootstrap.cc:654] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:30.739167 22436 tablet_bootstrap.cc:492] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: No bootstrap required, opened a new log
I20260812 06:19:30.739252 22436 ts_tablet_manager.cc:1403] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:30.739735 22436 raft_consensus.cc:359] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "927c435634314255a68b2909026be60e" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45851 } }
I20260812 06:19:30.739836 22436 raft_consensus.cc:385] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:30.739894 22436 raft_consensus.cc:740] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 927c435634314255a68b2909026be60e, State: Initialized, Role: FOLLOWER
I20260812 06:19:30.740056 22436 consensus_queue.cc:260] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [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: "927c435634314255a68b2909026be60e" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45851 } }
I20260812 06:19:30.740132 22436 raft_consensus.cc:399] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:30.740192 22436 raft_consensus.cc:493] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:30.740253 22436 raft_consensus.cc:3060] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:30.741057 22436 raft_consensus.cc:515] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "927c435634314255a68b2909026be60e" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45851 } }
I20260812 06:19:30.741227 22436 leader_election.cc:304] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [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: 927c435634314255a68b2909026be60e; no voters: 
I20260812 06:19:30.741465 22436 leader_election.cc:290] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:30.741596 22439 raft_consensus.cc:2804] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:30.741835 22439 raft_consensus.cc:697] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 1 LEADER]: Becoming Leader. State: Replica: 927c435634314255a68b2909026be60e, State: Running, Role: LEADER
I20260812 06:19:30.741853 22436 ts_tablet_manager.cc:1434] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:30.741895 22420 heartbeater.cc:499] Master 127.21.94.254:35189 was elected leader, sending a full tablet report...
I20260812 06:19:30.742040 22439 consensus_queue.cc:237] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [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: "927c435634314255a68b2909026be60e" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45851 } }
I20260812 06:19:30.743476 22224 catalog_manager.cc:5719] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e reported cstate change: term changed from 0 to 1, leader changed from <none> to 927c435634314255a68b2909026be60e (127.21.94.193). New cstate: current_term: 1 leader_uuid: "927c435634314255a68b2909026be60e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "927c435634314255a68b2909026be60e" member_type: VOTER last_known_addr { host: "127.21.94.193" port: 45851 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:30.827783 21883 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.078s	user 0.013s	sys 0.020s
I20260812 06:19:30.958288 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=15.086190
I20260812 06:19:31.085477 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.127s	user 0.087s	sys 0.032s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":916,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34569,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1000}
I20260812 06:19:31.086362 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:31.200999 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.114s	user 0.089s	sys 0.023s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12426369,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1431,"lbm_read_time_us":7655,"lbm_reads_lt_1ms":263,"lbm_write_time_us":17589,"lbm_writes_lt_1ms":243,"mutex_wait_us":53,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":544,"threads_started":5,"update_count":1000}
I20260812 06:19:31.201896 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba): free 11976772 bytes of WAL
I20260812 06:19:31.202230 22325 log_reader.cc:385] T 02363bf1cfc446fdb92fd4e05951d4ba: removed 1 log segments from log reader
I20260812 06:19:31.202302 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000001 (ops 1-6)
I20260812 06:19:31.205427 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:31.206092 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba): 12308960 bytes on disk
I20260812 06:19:31.206707 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:31.207268 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=8.142062
I20260812 06:19:31.242362 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.035s	user 0.015s	sys 0.017s Metrics: {"bytes_written":9846045,"delete_count":0,"lbm_write_time_us":13908,"lbm_writes_lt_1ms":243,"reinsert_count":0,"update_count":1200}
I20260812 06:19:31.243000 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.196750
I20260812 06:19:31.259449 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.016s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":3231,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:19:31.260025 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:31.391075 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.131s	user 0.092s	sys 0.038s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528862,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":860,"lbm_read_time_us":9472,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23102,"lbm_writes_lt_1ms":343,"mutex_wait_us":374,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":1500}
I20260812 06:19:31.391721 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:31.441318 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.049s	user 0.021s	sys 0.017s Metrics: {"bytes_written":12307531,"delete_count":0,"lbm_write_time_us":18314,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:31.441946 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:31.455246 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.455819 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:31.605372 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.149s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631353,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1017,"lbm_read_time_us":10376,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27622,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:19:31.606053 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:31.661058 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.055s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19235,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:31.661685 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:31.675057 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.675861 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:31.824396 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.148s	user 0.128s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1031,"lbm_read_time_us":10088,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29258,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:19:31.825191 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:31.876881 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.051s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19379,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:31.877601 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:31.891077 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.891819 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:32.043061 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.151s	user 0.125s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":734,"lbm_read_time_us":10436,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28296,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:32.043702 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:32.105789 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.062s	user 0.040s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20342,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.106526 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:32.121289 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.121824 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:32.293701 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.172s	user 0.115s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":13332,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27971,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:19:32.294517 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:32.347499 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.053s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19562,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.348174 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:32.366423 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.367087 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:32.510387 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.143s	user 0.110s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":10197,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28852,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:32.511337 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:32.560456 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.049s	user 0.029s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18548,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.561178 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:32.575191 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.576126 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:32.606453 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":287,"dirs.run_wall_time_us":2209,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1730,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:32.607298 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba): free 120553379 bytes of WAL
I20260812 06:19:32.607568 22325 log_reader.cc:385] T 02363bf1cfc446fdb92fd4e05951d4ba: removed 12 log segments from log reader
I20260812 06:19:32.607645 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000002 (ops 7-11)
I20260812 06:19:32.607703 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000003 (ops 12-16)
I20260812 06:19:32.607761 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000004 (ops 17-20)
I20260812 06:19:32.607806 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000005 (ops 21-25)
I20260812 06:19:32.607846 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000006 (ops 26-30)
I20260812 06:19:32.607887 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000007 (ops 31-35)
I20260812 06:19:32.607926 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000008 (ops 36-40)
I20260812 06:19:32.607966 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000009 (ops 41-44)
I20260812 06:19:32.608006 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000010 (ops 45-49)
I20260812 06:19:32.608057 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000011 (ops 50-54)
I20260812 06:19:32.608094 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000012 (ops 55-59)
I20260812 06:19:32.608134 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000013 (ops 60-64)
I20260812 06:19:32.636754 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:32.637303 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba): 463 bytes on disk
I20260812 06:19:32.637792 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.638301 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=3.181125
I20260812 06:19:32.652940 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5287,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:32.653439 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:32.664318 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:32.664837 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:32.887782 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.223s	user 0.153s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":909,"lbm_read_time_us":16187,"lbm_reads_lt_1ms":674,"lbm_write_time_us":43526,"lbm_writes_lt_1ms":643,"mutex_wait_us":102,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20608,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:19:32.888599 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=14.095187
I20260812 06:19:32.947679 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.059s	user 0.046s	sys 0.004s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.948390 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:32.962769 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.963397 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:33.145980 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.182s	user 0.116s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":12730,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34237,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:19:33.146872 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=12.110812
I20260812 06:19:33.194885 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.048s	user 0.041s	sys 0.000s Metrics: {"bytes_written":13784348,"delete_count":0,"lbm_write_time_us":20829,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:19:33.195632 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.196750
I20260812 06:19:33.223349 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.027s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3036010,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:19:33.223886 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:33.234756 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.235541 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:33.425726 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.190s	user 0.109s	sys 0.074s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":242,"lbm_read_time_us":14041,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33258,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:33.426642 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=11.118625
I20260812 06:19:33.481984 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.055s	user 0.027s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19677,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:33.483004 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:33.496850 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.497648 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:33.665737 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.168s	user 0.093s	sys 0.072s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":211,"lbm_read_time_us":12265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27845,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:33.666570 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=11.118625
I20260812 06:19:33.710963 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19520,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:33.711680 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:33.741042 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.029s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6019,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.741628 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:33.759989 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.018s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.760880 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:33.961725 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.201s	user 0.114s	sys 0.079s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":503,"lbm_read_time_us":12841,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32064,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:33.962345 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=11.118625
I20260812 06:19:34.006140 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.044s	user 0.031s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19623,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:34.007170 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:34.027889 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6414,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.028543 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:34.175632 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.147s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":8898,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29698,"lbm_writes_lt_1ms":443,"mutex_wait_us":110,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:34.176404 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:34.215171 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.038s	user 0.036s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16125,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.215828 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:34.252658 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.037s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1587,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2049,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:34.253399 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba): free 121006441 bytes of WAL
I20260812 06:19:34.253666 22325 log_reader.cc:385] T 02363bf1cfc446fdb92fd4e05951d4ba: removed 12 log segments from log reader
I20260812 06:19:34.253715 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000014 (ops 65-69)
I20260812 06:19:34.253749 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000015 (ops 70-74)
I20260812 06:19:34.253818 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000016 (ops 75-79)
I20260812 06:19:34.253849 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000017 (ops 80-84)
I20260812 06:19:34.253892 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000018 (ops 85-89)
I20260812 06:19:34.253934 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000019 (ops 90-94)
I20260812 06:19:34.253973 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000020 (ops 95-99)
I20260812 06:19:34.254006 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000021 (ops 100-104)
I20260812 06:19:34.254047 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000022 (ops 105-108)
I20260812 06:19:34.254089 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000023 (ops 109-113)
I20260812 06:19:34.254139 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000024 (ops 114-118)
I20260812 06:19:34.254184 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000025 (ops 119-123)
I20260812 06:19:34.282317 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:34.282891 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba): 462 bytes on disk
I20260812 06:19:34.283530 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.284133 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=6.157687
I20260812 06:19:34.310887 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.027s	user 0.007s	sys 0.016s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":11240,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:34.311578 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:34.497494 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.186s	user 0.137s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733727,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":10985,"lbm_reads_lt_1ms":568,"lbm_write_time_us":35280,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"thread_start_us":103,"threads_started":1,"update_count":2500}
I20260812 06:19:34.498648 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=14.095187
I20260812 06:19:34.551293 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.052s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23598,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.551983 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:34.730939 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.179s	user 0.092s	sys 0.082s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":966,"lbm_read_time_us":12370,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28353,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":56960,"update_count":2000}
I20260812 06:19:34.732364 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=11.118625
I20260812 06:19:34.808046 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.075s	user 0.033s	sys 0.020s Metrics: {"bytes_written":13661280,"delete_count":0,"lbm_write_time_us":22876,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1665}
I20260812 06:19:34.808619 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=5.165500
I20260812 06:19:34.845719 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.037s	user 0.024s	sys 0.007s Metrics: {"bytes_written":6851285,"delete_count":0,"lbm_write_time_us":10659,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:19:34.846971 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:34.857818 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.011s	user 0.000s	sys 0.004s Metrics: {"bytes_written":1312956,"delete_count":0,"lbm_write_time_us":1627,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:19:34.858362 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.196750
I20260812 06:19:34.868722 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:34.869232 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:35.107363 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.238s	user 0.163s	sys 0.074s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":837,"lbm_read_time_us":18759,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39027,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":3000}
I20260812 06:19:35.108217 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=14.095187
I20260812 06:19:35.171814 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.063s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22998,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.172451 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:35.184917 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.185456 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:35.394248 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.208s	user 0.144s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":232,"lbm_read_time_us":15179,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37638,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:35.395200 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:35.440035 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.045s	user 0.015s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20608,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.440702 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:35.455005 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.455520 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:35.633394 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.178s	user 0.099s	sys 0.072s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1242,"lbm_read_time_us":11781,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27302,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:19:35.634305 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:35.680385 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.046s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19401,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.681108 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:35.694471 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.695187 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:35.857390 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.162s	user 0.104s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":68,"lbm_read_time_us":13138,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":32262,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:19:35.858434 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=10.126437
I20260812 06:19:35.907625 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.049s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18994,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.908259 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:35.921511 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.922084 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:35.954170 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushMRSOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1389,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1649,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:35.954964 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba): free 120553628 bytes of WAL
I20260812 06:19:35.955260 22325 log_reader.cc:385] T 02363bf1cfc446fdb92fd4e05951d4ba: removed 12 log segments from log reader
I20260812 06:19:35.955338 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000026 (ops 124-128)
I20260812 06:19:35.955387 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000027 (ops 129-132)
I20260812 06:19:35.955423 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000028 (ops 133-137)
I20260812 06:19:35.955453 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000029 (ops 138-142)
I20260812 06:19:35.955478 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000030 (ops 143-147)
I20260812 06:19:35.955511 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000031 (ops 148-152)
I20260812 06:19:35.955547 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000032 (ops 153-156)
I20260812 06:19:35.955578 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000033 (ops 157-161)
I20260812 06:19:35.955618 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000034 (ops 162-166)
I20260812 06:19:35.955648 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000035 (ops 167-171)
I20260812 06:19:35.955682 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000036 (ops 172-176)
I20260812 06:19:35.955717 22325 log.cc:1079] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: Deleting log segment in path: /tmp/dist-test-task0MiLGB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515564176482-21883-0/minicluster-data/ts-0-root/wals/02363bf1cfc446fdb92fd4e05951d4ba/wal-000000037 (ops 177-181)
I20260812 06:19:35.988360 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: LogGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.033s	user 0.004s	sys 0.028s Metrics: {}
I20260812 06:19:35.988988 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba): 447 bytes on disk
I20260812 06:19:35.989586 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: UndoDeltaBlockGCOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:19:35.990255 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=3.181125
I20260812 06:19:36.011860 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.021s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5488,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:36.012375 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:36.024134 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.024664 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:36.225445 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.201s	user 0.156s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836362,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":566,"lbm_read_time_us":14723,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38111,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:19:36.226464 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=14.095187
I20260812 06:19:36.289855 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.063s	user 0.033s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27219,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.290608 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=2.188937
I20260812 06:19:36.314802 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.024s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.315419 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:36.478454 21883 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.651s	user 2.123s	sys 0.194s
I20260812 06:19:36.491139 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.176s	user 0.115s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":13028,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31374,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:19:36.491809 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=14.095187
I20260812 06:19:36.562733 21883 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.001s	sys 0.000s
I20260812 06:19:36.562783 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: FlushDeltaMemStoresOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.071s	user 0.030s	sys 0.037s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":33482,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.563418 21883 tablet_server.cc:179] TabletServer@127.21.94.193:0 shutting down...
I20260812 06:19:36.563568 22421 maintenance_manager.cc:419] P 927c435634314255a68b2909026be60e: Scheduling MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba): perf score=1.000000
I20260812 06:19:36.706483 22325 maintenance_manager.cc:643] P 927c435634314255a68b2909026be60e: MajorDeltaCompactionOp(02363bf1cfc446fdb92fd4e05951d4ba) complete. Timing: real 0.143s	user 0.099s	sys 0.044s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":401,"cfile_cache_miss_bytes":16409773,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":804,"lbm_read_time_us":8259,"lbm_reads_lt_1ms":413,"lbm_write_time_us":25625,"lbm_writes_lt_1ms":443,"mutex_wait_us":143,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:19:36.708189 21883 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:36.708748 21883 tablet_replica.cc:333] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e: stopping tablet replica
I20260812 06:19:36.708966 21883 raft_consensus.cc:2243] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:36.709203 21883 raft_consensus.cc:2272] T 02363bf1cfc446fdb92fd4e05951d4ba P 927c435634314255a68b2909026be60e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:36.726037 21883 tablet_server.cc:196] TabletServer@127.21.94.193:0 shutdown complete.
I20260812 06:19:36.748027 21883 master.cc:562] Master@127.21.94.254:35189 shutting down...
I20260812 06:19:36.752161 21883 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:36.752410 21883 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:36.752522 21883 tablet_replica.cc:333] T 00000000000000000000000000000000 P 853f156c409d4696b5f0d30b78005257: stopping tablet replica
I20260812 06:19:36.765429 21883 master.cc:584] Master@127.21.94.254:35189 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6268 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12676 ms total)

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